▪ ADMIN COMMAND 'trace on info info_level' command, see TRACE,
▪ SET SQL INFO ON LEVEL info_level FILE file_name statement, see SET SQL.
By default, the trace information is output to the soltrace.out file in the solidDB working directory. You can also specify the output file by using the SQL.InfoFileName parameter. This is recommended since the soltrace.out file might contain information from several sources.
Examples
[SQL] Info = 1 InfoFileName = solidsql_trace.txt
The following command turns on the SQL Info facility on level 3, outputting the trace information to the my_query.txt file in the working directory. This SQL Info facility is turned on only for the client that executes the statement:
SET SQL INFO ON LEVEL 1 FILE 'my_query.txt'
The following SQL statement turns off the SQL Info facility:
SET SQL INFO OFF
Analyzing Monitor facility trace output:
The Monitor facility provides information that you can use to analyze and tune performance at the individual SQL statement level.
The following example shows the contents of the Monitor output in soltrace.out for a solidDB server that is running a simplified transaction from a benchmark. In the example, the following statements are executed:
▪ SET
▪ SELECT (2 statements)
▪ UPDATE
▪ INSERT
2012-11-17 09:21:22 Version: 7.0.0.0 Build 2012-10-03 Operating system: Linux 2.6.18 AMD64 64bit MT solidDB 200.0 2012-11-17 09:21:23 User 'DBA' connected, user id 23, machine id solidhost.unicom.com (127.0.0.1). 2012-11-17 09:21:23.676 23:0:opencursor SQL_CUR1 'SET PASSTHROUGH READ NONE WRITE NONE' 2012-11-17 09:21:23.676 23:0:execute SET PASSTHROUGH READ NONE WRITE NONE 2012-11-17 09:21:23.676 23:0:exec rowcount 0 2012-11-17 09:21:23.677 23:1:opencursor SQL_CUR2 'Select C_LAST, C_CREDIT, C_DISCOUNT, W_TAX from CUSTOMER, WAREHOUSE where C_W_ID = ? and C_D_ID = ? and C_ID = ? and W_ID = ?' 2012-11-17 09:21:23.677 23:2:opencursor SQL_CUR3 'Select D_NEXT_O_ID, D_TAX from DISTRICT where D_W_ID = ? and D_ID = ? for update' 2012-11-17 09:21:23.678 23:3:opencursor SQL_CUR4 'Update DISTRICT set D_NEXT_O_ID = ? where D_W_ID = ? and D_ID = ?' 2012-11-17 09:21:23.678 23:4:opencursor SQL_CUR5 'Insert into ORDERS values (?, ?, ?, ?, ?, ?, ?, ?)' 2012-11-17 09:21:23.678 23:1:execute Select C_LAST, C_CREDIT, C_DISCOUNT, W_TAX from CUSTOMER, WAREHOUSE where C_W_ID = ? and C_D_ID = ? and C_ID = ? and W_ID =? 2012-11-17 09:21:23.678 23:1:param 1:3838 2012-11-17 09:21:23.678 23:1:param 2:2 2012-11-17 09:21:23.678 23:1:param 3:23 2012-11-17 09:21:23.678 23:1:param 4:3838 2012-11-17 09:21:23.679 23:1:fetch next, 1 rows, total 1 2012-11-17 09:21:23.679 23:2:execute Select D_NEXT_O_ID, D_TAX from DISTRICT where D_W_ID = ? and D_ID = ? for update 2012-11-17 09:21:23.679 23:2:param 1:3838 2012-11-17 09:21:23.679 23:2:param 2:2 2012-11-17 09:21:23.679 23:2:fetch next, 1 rows, total 1 2012-11-17 09:21:23.679 23:3:execute Update DISTRICT set D_NEXT_O_ID = ? where D_W_ID = ? and D_ID = ? 2012-11-17 09:21:23.679 23:3:param 1:32 2012-11-17 09:21:23.679 23:3:param 2:3838 2012-11-17 09:21:23.679 23:3:param 3:2 2012-11-17 09:21:23.679 23:3:exec rowcount 1 2012-11-17 09:21:23.679 23:4:execute Insert into ORDERS values (?, ?, ?, ?, ?, ?, ?, ?) 2012-11-17 09:21:23.680 23:4:param 1:31 2012-11-17 09:21:23.680 23:4:param 2:23 2012-11-17 09:21:23.680 23:4:param 3:2 2012-11-17 09:21:23.680 23:4:param 4:3838 2012-11-17 09:21:23.680 23:4:param 5:2012-11-17 09:21:23 2012-11-17 09:21:23.680 23:4:param 6:NULL 2012-11-17 09:21:23.680 23:4:param 7:8 2012-11-17 09:21:23.680 23:4:param 8:1 2012-11-17 09:21:23.680 23:4:exec rowcount 1 2012-11-17 09:21:23.680 23:transopt commit (6) 2012-11-17 09:21:23.680 23:0:close 2012-11-17 09:21:23.680 23:1:close 2012-11-17 09:21:23.680 23:2:close 2012-11-17 09:21:23.681 23:3:close 2012-11-17 09:21:23.681 23:4:close 2012-11-17 09:21:23 User 'DBA' disconnected, user id 23, machine id coralxib02.orolab.UNICOM.com (127.0.0.1).
The output can be divided into four columns as follows:
2012-11-17 09:21:23.679 | 23: | 3: | execute Update DISTRICT set D_NEXT_O_ID = ? where D_W_ID = ? and D_ID = ?
Timestamp (2012-11-17 09:21:23.679)
The first column is the time stamp. To ensure that the output has millisecond precision, the SRV.TraceSecDecimals parameter must be set to 3 (default).
Connection ID (23)
The second column is the connection ID. This number identifies each client connection to the solidDB server uniquely. In the example, only one connection is used, which is represented by connection ID 23. The example also shows when the user connected and disconnected.
Statement ID or transaction operation (3)
The column token is either a statement ID or a transaction level operation. The example shows the output from five SQL statements that are run within one transaction. The statement IDs for the five statements vary from 0 to 4. When a workload is running with more than one client that runs many SQL statements, the combination of connection ID and statement ID can identify each entry in the trace output uniquely. When the third token is not the statement ID, it is usually a transaction level operation, such as commit or rollback.
You can use grep or search facilities in any file viewing utility to use the combination to isolate and view one sequence of operations quickly.
To limit the amount of output the server produces, you can enable the Monitor facility for a specific user only by issuing the following command:
ADMIN COMMAND 'monitor on user username'
Trace data (execute Update DISTRICT set D_NEXT_O_ID = ? where D_W_ID = ? and D_ID = ?)
The fourth column shows the actual trace data for the operation. It can be the actual SQL statement being prepared or executed, the parameters being used, or another statement level operation that the server is performing.
Example: Analyzing the Monitor facility output
SELECT statement (ID 2)
Focusing on the SELECT statement with ID 2, you can see that the start timestamp for the prepare, shown as open cursor followed by the internally assigned cursor identifier is 2010-11-17 09:21:23.677. The execute started at 2010-11-17 09:21:23.679, which means that prepare took about 2 milliseconds to complete. The fetch completed at 2010-11-17 09:21:23.679, therefore it appears to have taken 0 milliseconds. The 0 millisecond duration typically means that the execution completed in sub-milliseconds or microseconds. Because the timer precision cannot be set to show microseconds, microsecond-level information is not available. Because of the precision limitation, the duration of the operations is approximate.
In the example output, the prepare operation takes about twice as long as the execute operation. This aligns with the known fact that preparing SQL statements is more expensive than executing them. To optimize the performance of your database, prepare statements as few times as possible.
In the example output, the statement fetches a total of 1 row. Typically, the more rows you need to fetch, the longer the statement execution takes and the less advantage an in-memory database has over traditional disk-based database management systems.
INSERT statement (ID 4)
Focusing on the INSERT statement with ID 4, you can see that the prepare operation started at 2010-11-17 09:21:23.678, the execute started at 2010-11-17 09:21:23.679, and the execute completed at 2010-11-17 09:21:23.680. By looking at the time stamps, you can see the prepare and the execute each took about 1 millisecond.
Transaction duration
You can use the timestamp information to calculate the duration of a transaction. In the example, the transaction executed by connection ID 23 started at 2010-11-17 09:21:23.676. The end of the transaction execution is marked by the by the operation transopt commit (6) (the digit 6 in parentheses is an internal identifier for a commit transaction operation). The timestamp associated with transopt commit (6) is 2010-11-17 09:21:23.680. It took about 4 milliseconds to complete the transaction.
Reconstructing executed SQL statements
The trace output shows the parameter values for the dynamic SQL statements. You can use the trace output to reconstruct the actual SQL statements that were executed. For example, you can execute the statements with the same parameters in solidDB SQL Editor (solsql) to analyze the statement further.