But isn't the fact that only next command can complete the log for the previous one (when performed on the same client Statement) affecting the time precision of the logs?

Or would they?

Command logging: last command's log is not ended ------------------------------------------------ Key: TEIID-3596 URL: https://issues.jboss.org/browse/TEIID-3596 Project: Teiid Issue Type: Bug Components: Query Engine Affects Versions: 8.7.1.6_2 Reporter: Jan Stastny Assignee: Steven Hawkins There are incomplete entries when performing queries on some vdb and examining the org.teiid.COMMAND_LOG entries in server.log. From the logs it seems, that the closing entry for a user command is not logged until either another command is performed or the server is shut down. The following logs appears right after the command is performed: {code:plain} [org.teiid.COMMAND_LOG] (New I/O worker #64) START USER COMMAND: startTime=2015-07-28 13:43:18.441 requestID=rfFDiTxhxLGL.0 txID=null sessionID=rfFDiTxhxLGL applicationName=JDBC principal=user@teiid-security vdbName=Portfolio vdbVersion=1 sql=select * from product [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1) START DATA SRC COMMAND: startTime=2015-07-28 13:43:18.54 requestID=rfFDiTxhxLGL.0 sourceCommandID=0 executionID=0 txID=null modelName=Accounts translatorName=translator-h2 sessionID=rfFDiTxhxLGL principal=user@teiid-security sql=SELECT g_0.ID, g_0.SYMBOL, g_0.COMPANY_NAME FROM Accounts.PRODUCT AS g_0 [org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue2) END SRC COMMAND: endTime=2015-07-28 13:43:18.548 requestID=rfFDiTxhxLGL.0 sourceCommandID=0 executionID=0 txID=null modelName=Accounts translatorName=translator-h2 sessionID=rfFDiTxhxLGL principal=user@teiid-security finalRowCount=25 {code} while the following appers only when the server is shut down (notice the time difference between this one and preceding ones): {code:plain} [org.teiid.COMMAND_LOG] (New I/O worker #64) CANCEL USER COMMAND: endTime=2015-07-28 13:43:29.152 requestID=rfFDiTxhxLGL.0 txID=null sessionID=rfFDiTxhxLGL principal=user@teiid-security vdbName=Portfolio vdbVersion=1 finalRowCount=null {code} If there is another command following, the previous command log entry is completed (but it can take even minutes): {code:plain} [org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue3) END USER COMMAND: endTime=2015-07-28 14:18:59.511 requestID=q97k+Z4gwV64.0 txID=null sessionID=q97k+Z4gwV64 principal=user@teiid-security vdbName=Portfolio vdbVersion=1 finalRowCount=25 {code} Also the ending log entry of one command and opening entry of another appear in any order.