obproxy_slow.log records logs for slow SQL queries, which refer to queries whose execution time is greater than the threshold (default value: 500 ms) specified by the slow_query_time_threshold parameter.
Log format
Log printing time,Logical tenant name,TraceId,RpcId,Logical database name,Physical database information (cluster:tenant:database),Database type (OB/RDS),Logical table name,Physical table name,SQL command,SQL type (CRUD),Execution result (success/failed),Error code (empty for success),SQL statement,Total execution time (μs),ODP processing time,Connection establishment time,OBServer node execution time,Current thread name,Ignorable fieldswhere
The
SQL commandcan beCOM_QUERYorCOM_STMT_PREPARE.The
total execution timeincludes the internal SQL execution time.The
current thread nameindicates the internal thread ID in ODP.
Log example
2022-07-11 14:32:51.758270,undefined,,,,obcluster:sys:test,OB_MYSQL,,,COM_QUERY,SELECT,success,,select sleep(3),3041116us,409us,0us,3039883us,Y0-7F4B1CEA13A0,,,,0,11.xxx.xxx.53:33041
obproxy.log also records logs for slow SQL queries with the keyword Slow Query. The logs in obproxy.log provide more details. For example, after you execute the SQL statement select sleep(3) from dual, you can find the following log in obproxy.log:
[2022-07-11 14:32:51.758195] WARN [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:8425) [74744][Y0-7F4B1CEA13A0] [lt=7] [dc=0] Slow Query: ((
client_ip={127.0.0.1:50422}, // The IP address of the client that executes the SQL query.
server_ip={11.xxx.xxx.53:33041}, // The IP address of the OBServer node to which the SQL query is routed.
obproxy_client_port={100.xxx.xxx.179:52052}, // The IP address of the client connected to OceanBase Database.
server_trace_id=Y81100B7C0535-0005E3460FBBE3CD-0-0, // The trace ID in the execution process of the OBServer node.
route_type=ROUTE_TYPE_NONPARTITION_UNMERGE_LOCAL, // The routing strategy used for the SQL query.
user_name=root, // The username.
tenant_name=sys, // The tenant name.
cluster_name=obcluster, // The cluster name.
logic_database_name=, // The name of the logical database.
logic_tenant_name=, // The logical tenant name.
ob_proxy_protocol=0, // The protocol type.
cs_id=14, // The connection ID used during client logon, which is assigned by ODP.
proxy_sessid=7230691598940700681, // The connection ID recorded when the client accesses OceanBase Database.
ss_id=21,
server_sessid=3221588238, // The connection ID of the SQL query on the target OBServer node, which is assigned by the OBServer node.
sm_id=14,
cmd_size_stats={
client_request_bytes:20, // The size of the request packet sent by the client to ODP.
server_request_bytes:38, // The size of the request packet sent by ODP to the target OBServer node.
server_response_bytes:0, // The size of the response packet sent by the target OBServer node to ODP.
client_response_bytes:71}, // The size of the response packet sent by ODP to the client.
cmd_time_stats={
client_transaction_idle_time_us=0 // The time interval, in μs, between the start of the current SQL query and the end of the last SQL query in the transaction.
client_request_read_time_us=97, // The time, in μs, spent by ODP on reading the request packet from the client.
client_request_analyze_time_us=95, // The time, in μs, spent by ODP on analyzing the SQL query sent by the client.
cluster_resource_create_time_us=0, // The time, in μs, spent by ODP on creating cluster resources (only when the cluster is accessed for the first time).
pl_lookup_time_us=0, // The time, in μs, spent on retrieving the routing table based on the SQL query.
pl_process_time_us=0, // The time, in μs, spent on processing the routing table.
congestion_control_time_us=21, // The time, in μs, spent on retrieving the blocklist based on the SQL query.
congestion_process_time_us=3, // The time, in μs, spent on checking and filtering based on the blocklist.
do_observer_open_time_us=55, // The time, in μs, spent on obtaining an available connection from the target OBServer node, including connect_time.
server_connect_time_us=0, // The time, in μs, spent on creating a connection with the target OBServer node.
server_sync_session_variable_time_us=0, // The time, in μs, spent on initializing the target connection. The initialization process includes saving the login information (saved_login) and synchronizing the database, system variables, the last insert ID (the ID of the last record you added to your database, represented by last_insert_id), and the transaction start time (start_trans).
server_send_saved_login_time_us=0, // The time, in μs, spent on saving the logon information for the target connection.
server_send_use_database_time_us=0, // The time, in μs, spent on synchronizing the database for the target connection.
server_send_session_variable_time_us=0, // The time, in μs, spent on synchronizing modified system variables for the target connection.
server_send_all_session_variable_time_us=0, // The time, in μs, spent on synchronizing all system variables for the target connection.
server_send_last_insert_id_time_us=0, // The time, in μs, spent on synchronizing the last insert ID (last_insert_id) for the target connection.
server_send_start_trans_time_us=0, // The time, in μs, spent on synchronizing the transaction start time (start_trans/begin) for the target connection.
build_server_request_time_us=23, // The time, in μs, spent on creating the request packet to be sent to the target OBServer node.
plugin_compress_request_time_us=0, // The time, in μs, spent on compressing the request packet.
prepare_send_request_to_server_time_us=409, // The total time, in μs, from when ODP receives the request from the client till it forwards the request to the OBServer node for execution, which is normally the sum of all the previous time.
server_request_write_time_us=32, // The time, in μs, spent by ODP on sending the request packet to the target OBServer node.
server_process_request_time_us=3039883, // The time, in μs, spent by the target OBServer node on executing the SQL query.
server_response_read_time_us=67, // The time, in μs, spent by ODP on reading the response packet from the target OBServer node.
plugin_decompress_response_time_us=59, // The time, in μs, spent on decompressing the response packet.
server_response_analyze_time_us=70, // The time, in μs, spent on analyzing the response packet.
ok_packet_trim_time_us=0, // The time, in μs, spent on trimming the last OK packet from the response packet.
client_response_write_time_us=185, // The time, in μs, spent by ODP on sending the response packet to the client.
request_total_time_us=3041116} // The total time, in μs, spent by ODP on processing the request. The value is the sum of all the previous time.
sql=select sleep(3) // The SQL query sent by the client.
))
References
For more information about the slow_query_time_threshold parameter, see slow_query_time_threshold.