{"record":{"id":"e0efe66f8c852459","repo":"hibernate/hibernate-orm","slug":"starttimenanos-starttimenanos-should-be-great","errorCode":null,"errorMessage":"startTimeNanos [${startTimeNanos}] should be greater than 0","messagePattern":"startTimeNanos \\[(.+?)\\] should be greater than 0","errorType":"exception","errorClass":"IllegalArgumentException","httpStatus":null,"severity":"error","filePath":"hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlStatementLogger.java","lineNumber":143,"sourceCode":"\n\t\t\tLOG.debug( statement );\n\t\t\tif ( logToStdout ) {\n\t\t\t\tString prefix = highlight ? \"\\u001b[35m[Hibernate]\\u001b[0m \" : \"Hibernate: \";\n\t\t\t\tSystem.out.println( prefix + statement );\n\t\t\t}\n\t\t}\n\t}\n\n\t/**\n\t * Log a slow SQL query\n\t *\n\t * @param sql The SQL query.\n\t * @param startTimeNanos Start time in nanoseconds.\n\t */\n\tpublic void logSlowQuery(final String sql, final long startTimeNanos, final JdbcSessionContext context) {\n\t\tif ( logSlowQuery >= 1 ) {\n\t\t\tif ( startTimeNanos <= 0 ) {\n\t\t\t\tthrow new IllegalArgumentException(\n\t\t\t\t\t\t\"startTimeNanos [\" + startTimeNanos + \"] should be greater than 0\" );\n\t\t\t}\n\n\t\t\tfinal long queryExecutionMillis = elapsedFrom( startTimeNanos );\n\n\t\t\tif ( queryExecutionMillis > logSlowQuery ) {\n\t\t\t\tlogSlowQueryInternal( context, queryExecutionMillis, sql );\n\t\t\t}\n\t\t}\n\t}\n\n\tprivate static long elapsedFrom(final long startTimeNanos) {\n\t\treturn TimeUnit.NANOSECONDS.toMillis( System.nanoTime() - startTimeNanos );\n\t}\n\n\t@AllowSysOut\n\tprivate void logSlowQueryInternal(final JdbcSessionContext context, final long queryExecutionMillis, final String sql) {\n\t\tfinal String logData = \"Slow query took \" + queryExecutionMillis + \" milliseconds [\" + sql + \"]\";","sourceCodeStart":125,"sourceCodeEnd":161,"githubUrl":"https://github.com/hibernate/hibernate-orm/blob/fad1729dce015f908198d57a8d80274a30f905a5/hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlStatementLogger.java#L125-L161","documentation":"SqlStatementLogger.logSlowQuery(String, long, JdbcSessionContext) is invoked after each statement when a slow-query threshold is configured (milliseconds; 0 disables - set via hibernate's LOG_QUERIES_SLOWER_THAN_MS / hibernate.log_slow_query). With a threshold >= 1 it demands a startTimeNanos greater than 0 - a System.nanoTime() timestamp captured immediately before execution - and throws IllegalArgumentException for 0 or negative values to reject an unset or bogus start time.","triggerScenarios":"Custom integrations (statement observers, wrapped JDBC resources, perf tools) calling logSlowQuery(sql, 0, context) because no start time was recorded; code passing an arbitrary epoch like -1 or a default long field; passing a placeholder because the statement was prepared in one component and executed in another that lost the timestamp.","commonSituations":"Enabling slow-query logging in a custom SessionFactory customization or connection wrapper that instruments execution but never captured System.nanoTime(); test harnesses invoking the logger directly; integrations migrated from older signatures that took milliseconds instead of nanoseconds.","solutions":["Capture long t0 = System.nanoTime() immediately before statement execution and pass t0","Only call logSlowQuery when you actually recorded a start time; skip the call otherwise","Use System.nanoTime() (monotonic), never System.currentTimeMillis() or guessed constants","Keep the capture and the logSlowQuery call on the same code path so the timestamp cannot be lost"],"exampleFix":"// before\nlong startTimeNanos = 0; // never set\nstmt.execute(sql);\nlogger.logSlowQuery(sql, startTimeNanos, context); // IllegalArgumentException\n\n// after\nlong t0 = System.nanoTime();\nstmt.execute(sql);\nlogger.logSlowQuery(sql, t0, context);","handlingStrategy":"validation","validationCode":"// Capture and pass a real nanoTime; never call the logger without one\nfinal long startTimeNanos = System.nanoTime();\nstmt.execute(sql);\nif (startTimeNanos > 0) {\n    sqlStatementLogger.logSlowQuery(sql, startTimeNanos, context);\n}","typeGuard":null,"tryCatchPattern":"if (startTimeNanos > 0) {\n    sqlStatementLogger.logSlowQuery(sql, startTimeNanos, context);\n} // else: no valid start time was captured - skipping the slow-query log is correct","preventionTips":["Capture System.nanoTime() in the same try block that executes the statement","Use System.nanoTime() (monotonic), never System.currentTimeMillis() or constants","Keep the capture point and the logSlowQuery call in one component so the value cannot be lost"],"tags":["hibernate","jdbc","logging","slow-query","nanotime","argument-validation","illegal-argument"],"backgroundTag":"non-positive-timestamp-argument","analyzedSha":"fad1729dce015f908198d57a8d80274a30f905a5","analyzedAt":"2026-08-22T04:13:57.527Z","schemaVersion":2},"datasetVersion":"2026-08-22T09:17:25.309Z"}