Monitoring logs

Three tools are available to resolve OceanBase Database Proxy (ODP) issues: ODP logs, Linux commands (including network commands, system commands, and text commands), and OceanBase Cloud Platform (OCP). Reference materials about Linux commands and OCP are common on the Internet. We recommend that you learn the related knowledge to facilitate troubleshooting.

This topic describes ODP logs of different types.

Audit logs

Audit logs are recorded in the obproxy_digest.log file. It records requests whose execution time exceeds the threshold specified by the query_digest_time_threshold parameter, and requests with incorrect responses.

• Log format

  Log printing time, current application name, trace ID, RPC ID, name of the logical data source, physical database information (cluster:tenant:database), database type (OB or RDS), name of the logical table, name of the physical table, SQL command, SQL type (CRUD), execution result (success or failed), error code (empty when the execution result is success), SQL statement, total SQL execution time (in us), pre-execution time, link establishment time, database execution time, current thread name, shard name, whether BT mode is used, system penetration data, and penetration data
  

  Notes:

  • The SQL command can be COM_QUERY or COM_STMT_PREPARE.

  • The total execution time includes the execution time of internal SQL statements.

  • The current thread name indicates the internal thread ID of the ODP.

  • The information about the shard name and whether BT mode is used can be printed in logs only in V2.0.20 and later. The value 1 indicates that the BT mode is used and the value 0 indicates that the BT mode is not used.

  • The system penetration data indicates the disaster recovery information of the system.

• Example

  In this example, select sleep(3) from dual is used to simulate a slow SQL statement. After this statement is executed, view the obproxy_digest.log file. The log shows that the execution time on ODP is 409 μs and the execution time on the OBServer is 3039883 μs. The following example shows the content of the log:

  2022-07-11 14:32:51.758265,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
  # The log fields are separated with commas (,). If the SQL statement contains a comma, it will be replaced with %2C. The result after replacement by using tr ',' '\n' is as follows:
     1,2022-07-11 14:32:51.758265    # The log printing time.
     2,undefined          # It is for internal use. You do not need to pay attention to it.
     3,                   # It is for internal use. You do not need to pay attention to it.
     4,                   # It is for internal use. You do not need to pay attention to it.
     5,                   # It is for internal use. You do not need to pay attention to it.
     6,obcluster:sys:test  # The information about the physical database, in the format of cluster name:tenant name:database name.
     7,OB_MYSQL         # The database type.
     8,                 # The name of the logical table.
     9,                 # The name of the physical table.
     10,COM_QUERY       # The SQL command, for example, COM_QUERY or COM_STMT_PREPARE.
     11,SELECT          # The SQL type.
     12,success         # The execution result. Valid value: success or failed.
     13,                # The error code, which is empty when the execution result is success.
     14,select sleep(3) # The SQL statement.
     15,3041116us       # The total execution time in us, including the execution time of internal SQL statements.
     16,409us           # The pre-execution time.
     17,0us             # The connection establishment time.
     18,3039883us       # The database execution time.
     19,Y0-7F4B1CEA13A0 # The trace ID of the internal log of the ODP.
     20,                # It is for internal use. You do not need to pay attention to it.
     21,                # It is for internal use. You do not need to pay attention to it.
     22,                # It is for internal use. You do not need to pay attention to it.
     23,0               # It is for internal use. You do not need to pay attention to it.
     24,11.xxx.xxx.53:33041  # The address of the OBServer to route to.
  

In an audit log, the 14th line records the executed SQL statement, and the 15th and 16th lines record the detailed execution time. If the execution in the database is slow, the time recorded in the 18th line is long.

SQL execution statistic logs

The obproxy_stat.log file records the SQL execution statistic logs. By default, a statistic log is generated once every minute. The generation interval is specified by the monitor_stat_dump_interval parameter. In this log, you can view the SQL statements executed by ODP within one minute.

• Log format

Log printing time, current application name, name of the logical data source, physical database information (cluster:tenant:database), database type (OB or RDS), SQL type (CRUD), execution result (success or failed), error code (empty when the execution result is success), total requests, requests with an execution time in the range of [30 ms, 100 ms), requests with an execution time in the range of [100 ms, 500 ms), requests with an execution time greater than or equal to 500 ms, total execution time (in us, including the execution time of internal SQL statements), pre-execution time, and database execution time

• Example

  To check whether ODP has request traffic, view this log record. Example:

  2022-07-11 10:26:59.499204,undefined,,obcluster:sys:test,OB_MYSQL,SELECT,success,,1,1,0,0,41480us,332us,40369us
  
  # Log analysis
  1,2022-07-11 10:26:59.499204   # The log printing time.
  2,undefined      # The logical tenant name.
  3,               # The name of the logical database.
  4,obcluster:sys:test  # The information about the physical database, in the format of cluster name:tenant name:database name.
  5,OB_MYSQL  # The database type.
  6,SELECT    # The SQL type.
  7,success   # The execution result. Valid value: success or failed.
  8,          # The error code, which is empty when the execution result is success.
  9,1         # The total number of requests.
  10,1           # The number of requests whose execution time ranges from 30 ms to 100 ms.
  11,0           # The number of requests whose execution time ranges from 100 ms to 500 ms.
  12,0           # The number of requests whose execution time is greater than 500 ms.
  13,41480us     # The total execution time in us, including the execution time of internal SQL statements.
  14,332us       # The pre-execution time.
  15,40369u      # The database execution time.
  

Slow SQL request logs

The obproxy_slow.log file logs slow SQL requests. Requests with the execution time greater than the threshold (default value: 500 ms) specified by the slow_query_time_threshold parameter are recorded.

• Log format

  Log printing time, current application name, trace ID, RPC ID, name of the logical data source, physical database information (cluster:tenant:database), database type (OB or RDS), name of the logical table, name of the physical table, SQL command, SQL type (CRUD), execution result (success or failed), error code (empty when the execution result is success), SQL statement, total SQL execution time (in us), pre-execution time, link establishment time, database execution time, current thread name, system penetration data, and penetration data
  

  Notes:

  • The SQL command can be COM_QUERY or COM_STMT_PREPARE.

  • The total execution time includes the execution time of internal SQL statements.

  • The current thread name indicates the internal thread ID of the ODP.

  • The system penetration data indicates the disaster recovery information of the system.

• 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
  

The obproxy.log file also records slow SQL queries and the keyword is Slow Query. The information recorded in the obproxy.log file is more detailed. For example, after the select sleep(3) from dual SQL statement is executed, you can find the following information in the obproxy.log file:

[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 to which the SQL query is routed.
obproxy_client_port={100.xxx.xxx.179:52052},  // The address of the ODP that connects to the OBServer.
server_trace_id=Y81100B7C0535-0005E3460FBBE3CD-0-0, // The trace ID of the execution process in the target OBServer.
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 the 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 in the target OBServer. This ID is assigned by the OBServer.
sm_id=14,
cmd_size_stats={
    client_request_bytes:20,  // The size of the request packet sent by the client to the ODP.
    server_request_bytes:38,  // The size of the request packet sent by the ODP to the target OBServer.
    server_response_bytes:0,  // The size of the response packet sent by the target OBServer to the ODP.
    client_response_bytes:71}, // The size of the response packet sent by the ODP to the client.
cmd_time_stats={
    client_transaction_idle_time_us=0 // The time interval between the start of the current SQL query and the end of the last SQL query in the transaction. Unit: μs.
    client_request_read_time_us=97, // The time spent by the ODP on reading the request packets from the client socket. Unit: μs.
    client_request_analyze_time_us=95, // The time spent by the ODP on analyzing the SQL query sent by the client. Unit: μs.
    cluster_resource_create_time_us=0, // The time spent by the ODP on creating the cluster cache. The ODP needs to create the cluster cache only when it accesses the cluster for the first time. Unit: μs.
    pl_lookup_time_us=0,  // The time spent on retrieving the routing table based on the SQL query. Unit: μs.
    pl_process_time_us=0,  // The time spent on processing the routing table. Unit: μs.
    congestion_control_time_us=21,  // The time spent on retrieving the blacklist based on the SQL query. Unit: μs.
    congestion_process_time_us=3,  // The time spent on checking and filtering the blacklist based on the SQL query. Unit: μs.
    do_observer_open_time_us=55,  // The time spent on retrieving the available connections from the target OBServer, including the connection time (connect_time). Unit: μs.
        server_connect_time_us=0,  // The time spent on creating the connection between the client and the target OBServer. Unit: μs.
    server_sync_session_variable_time_us=0, // The time 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). Unit: μs.
        server_send_saved_login_time_us=0,  // The time spent on saving the logon information for the target connection. Unit: μs.
        server_send_use_database_time_us=0,  // The time spent on synchronizing the database for the target connection. Unit: μs.
        server_send_session_variable_time_us=0,  // The time spent on synchronizing modified system variables for the target connection. Unit: μs.
        server_send_all_session_variable_time_us=0,  // The time spent on synchronizing all system variables for the target connection. Unit: μs.
        server_send_last_insert_id_time_us=0, // The time spent on synchronizing the last insert ID (last_insert_id) for the target connection. Unit: μs.
        server_send_start_trans_time_us=0,  // The time spent on synchronizing the transaction start time (start_trans/begin) for the target connection. Unit: μs.
    build_server_request_time_us=23, // The time spent on creating the request packets to be sent to the target OBServer. Unit: μs.
    plugin_compress_request_time_us=0,  // The time spent on compressing the request packets. Unit: μs.
    prepare_send_request_to_server_time_us=409,  // The time elapsed from the moment OBProxy received the request from the client to the moment the request is forwarded to an OBServer for execution. The value of this parameter is the sum of the values of the preceding parameters. Unit: μs.
    server_request_write_time_us=32,  // The time spent by the ODP on sending the request packets to the target server socket. Unit: μs.
    server_process_request_time_us=3039883,  // The time spent by the OBServer on executing the SQL query. Unit: μs.
    server_response_read_time_us=67,  // The time spent by the ODP on reading the response packets from the server socket. Unit: μs.
    plugin_decompress_response_time_us=59, // The time spent on decompressing the response packets. Unit: μs.
    server_response_analyze_time_us=70,  // The time spent on analyzing the response packets. Unit: μs.
    ok_packet_trim_time_us=0,  // The time spent on trimming the last OK packet from the response packets. Unit: μs.
    client_response_write_time_us=185,  // The time spent by the ODP on sending the response packets to the client socket. Unit: μs.
    request_total_time_us=3041116}  // The total time spent by the ODP on processing the request. The value of this parameter is the sum of the values of the preceding parameters. Unit: μs.
sql=select sleep(3)   // The SQL query sent by the client.
))

ODP error logs

The obproxy_error.log file records ODP error logs. Queries with an execution error are logged in this log file, including ODP errors and errors returned by the OBServer.

• Log format

  Log printing time, current application name, trace ID, RPC ID, name of the logical data source, physical database information (cluster:tenant:database), database type (OB or RDS), name of the logical table, name of the physical table, SQL command, SQL type (CRUD), execution result (success or failed), error code (empty when the execution result is success), SQL statement, total SQL execution time (in us), pre-execution time, link establishment time, database execution time, current thread name, system penetration data, penetration data, and error details
  

  Notes:

  • The SQL command can be COM_QUERY or COM_STMT_PREPARE.

  • The total execution time includes the execution time of internal SQL statements.

  • The current thread name indicates the internal thread ID of the ODP.

  • The system penetration data indicates the disaster recovery information of the system.

• Example

  In the following example, the select obproxy_error from dual statement is used. The obproxy_error field in the statement is not enclosed by quotation marks and will be treated as a column. This results in an execution failure. The client returns the following error:

  MySQL [test]> select obproxy_error from dual;
  ERROR 1054 (42S22): Unknown column 'obproxy_error' in 'field list'
  

  The obproxy_error.log file records the following information for the error:

  2022-07-11 10:26:09.358231,undefined,,,,obcluster:sys:test,OB_MYSQL,,,COM_QUERY,SELECT,failed,1054,select obproxy_error from dual,42423us,454us,0us,41222us,Y0-7F4B1EF653A0,,,,0,11.xxx.xxx.53:33041,Unknown column 'obproxy_error' in 'field list'
  
  # Log analysis
  1,2022-07-11 10:26:09.358231    # The log printing time.
  2,undefined          # It is for internal use. You do not need to pay attention to it.
  3,                   # It is for internal use. You do not need to pay attention to it.
  4,                   # It is for internal use. You do not need to pay attention to it.
  5,                   # It is for internal use. You do not need to pay attention to it.
  6,obcluster:sys:test  # The information about the physical database, in the format of cluster name:tenant name:database name.
  7,OB_MYSQL         # The database type.
  8,                 # The name of the logical table.
  9,                 # The name of the physical table.
  10,COM_QUERY       # The SQL command, for example, COM_QUERY or COM_STMT_PREPARE.
  11,SELECT          # The SQL type.
  12,failed          # The execution result. Valid value: success or failed.
  13,1054            # The error code, which is empty when the execution result is success.
  14,select obproxy_error from dual  # The SQL statement.
  15,42423us         # The total execution time in us, including the execution time of internal SQL statements.
  16,454us           # The pre-execution time.
  17,0us             # The connection establishment time.
  18,41222us         # The database execution time.
  19,Y0-7F4B1EF653A0 # The trace ID of the internal log of the ODP.
  20,            # It is for internal use. You do not need to pay attention to it.
  21,           # It is for internal use. You do not need to pay attention to it.
  22,          # It is for internal use. You do not need to pay attention to it.
  23,0          # It is for internal use. You do not need to pay attention to it.
  24,11.xxx.xxx.53:33041  # The address of the OBServer to route to.
  25,Unknown column 'obproxy_error' in 'field list' # The error message.
  

  The 12th line shows an execution failure. The 27th line shows the address information about the OBServer that executed the SQL query. The 28th line shows the error message. You can determine, based on the preceding information, that a database execution failure occurred.

ODP throttling logs

The obproxy_limit.log file records ODP throttling logs. Throttled requests are logged in this file.

• Log format

  Log printing time, current application name, trace ID, RPC ID, name of the logical data source, physical database information (cluster:tenant:database), database type (OB or RDS), name of the logical table, name of the physical table, SQL command (such as COM_QUERY or COM_STMT_PREPARE), SQL type (CRUD), throttling status (RUNNING or OBSERVE), SQL statement, and SQL throttling rule name
  

• Example

  2020-03-18 21:26:54.871053,postmen,,,,postmen40:postmen_new0497_3279:postmen_r497,OB_MYSQL,,postmen_push_msg_4977,COM_QUERY,SELECT,RUNNING,SELECT    id%2C    gmt_create%2C    gmt_modified%2C    msg_id%2C    principal_id%2C    app_name%2C    target_utdid%2C    biz_id%2C    host%2C    status%2C    expire_time%2C    msg_data   FROM    postmen_push_msg_4977   WHERE    principal_id = 'W/jEKoLOxnwDABWmhzjgmK1V' AND    app_name = 'KOUBEI' AND    expire_time > 1584538014858 AND    status = 1,LIMIT_RULE_1
  

Prometheus

In addition to a log system, ODP further provides the Prometheus system for integration with different monitoring platforms. Prometheus provides information such as the total number of requests, execution time, number of frontend connections, and number of backend connections. The following table describes the monitoring metrics.