监控日志说明

解决 ODP 的问题时，有三大法宝：ODP 日志、Linux 命令（网络命令、系统命令和文本命令）和监控平台 OCP。其中 Linux 命令和监控平台的知识点十分通用，网络上资料很多，大家可以自行学习，掌握后对大家排查问题帮助很大。

本节我们主要介绍和 ODP 关系比较紧密的日志部分，ODP 的日志有多种类别，我们将分别介绍每种日志的作用，帮助大家排查问题。

审计日志

obproxy_digest.log 日志是审计日志，记录执行时间大于参数 query_digest_time_threshold 阈值（默认 100ms，主站是 2ms）的请求和错误响应请求。

• 日志格式

  日志打印时间,当前应用名,TraceId,RpcId,逻辑数据源名称,物理库信息(cluster:tenant:database),数据库类型(OB/RDS),逻辑表名,物理表名,SQL 命令,SQL 类型(CRUD),执行结果(success/failed),错误码(success 时为空),SQL,执行总耗时(ms),预执行时间,链接建立时间,数据库执行时间,当前线程名,shard_name,是否BT方式,系统穿透数据,穿透数据
  

  说明：

  • SQL 命令 显示为 COM_QUERY、COM_STMT_PREPARE 等。

  • 执行总耗时 包括内部 SQL 执行耗时。

  • 当前线程名 显示 ODP 的内部线程 ID。

  • shard_name 和 是否BT方式 需版本在 V2.0.20 及以上才会支持，其中 1 代表是 BT 方式，0 代表不是 BT 方式。

  • 系统穿透数据 将显示系统灾备信息等。

• 日志示例

  此处使用 select sleep(3) from dual 模仿慢 SQL，执行后查看 obproxy_digest.log，可以看到 ODP 执行花费了 409us，OceanBase 数据库执行花了 3039883us。内容如下：

  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
  
  
  # 日志通过逗号分隔，如果 SQL 中有逗号，会通过 %2C 替代，通过 tr ',' '\n' 替换结果如下
  1,2022-07-11 14:32:51.758265    #日志打印时间
  2,undefined          # 无需关注，内部使用
  3,                   # 无需关注，内部使用
  4,                   # 无需关注，内部使用
  5,                   # 无需关注，内部使用
  6,obcluster:sys:test  # 物理库信息（cluster:tenant:database）
  7,OB_MYSQL         # 数据库类型
  8,                 # 逻辑表名
  9,                 # 物理表名
  10,COM_QUERY       # SQL 命令（COM_QUERY、COM_STMT_PREPARE 等）
  11,SELECT          # SQL 类型
  12,success         # 执行结果（success/failed）
  13,                # 错误码（success 时为空）
  14,select sleep(3) # SQL 语句
  15,3041116us       # 执行总耗时（ms，包括内部 SQL 执行耗时）
  16,409us           # 预执行时间
  17,0us             # 建立连接时间
  18,3039883us       # 数据库执行时间
  19,Y0-7F4B1CEA13A0 # ODP 内部日志 trace_id
  20,                # 无需关注，内部使用
  21,                # 无需关注，内部使用
  22,                # 无需关注，内部使用
  23,0               # 无需关注，内部使用
  24,11.xxx.xxx.53:33041  # 路由到的 OceanBase 数据库的地址信息
  

  对于审计日志比较重要的是第 14 行记录了执行的 SQL，15 ~ 16 记录了详细的执行时间，如果数据库执行慢第 18 行的时间就会很长。

SQL 执行统计日志

obproxy_stat.log 日志是 SQL 执行统计日志，统计日志默认每分钟（由 monitor_stat_dump_interval 参数控制）输出一次，通过该日志可以查看 ODP 一分钟内 SQL 的执行情况。

• 日志格式

  日志打印时间,当前应用名,逻辑数据源名称,物理库信息(cluster:tenant:database),数据库类型(OB/RDS),SQL 类型(CRUD),执行结果(success/failed),错误码(success 时为空),总请求数量,[30 ms, 100 ms) 请求数量,[100 ms, 500 ms) 请求数量,[500 ms,+∞) 请求数量,执行总耗时(ms, 包括内部 SQL 执行耗时),预执行时间,数据库执行时间
  

• 日志示例

  若要查看 ODP 是否有请求流量，看该日志记录即可，如下：

  2022-07-11 10:26:59.499204,undefined,,obcluster:sys:test,OB_MYSQL,SELECT,success,,1,1,0,0,41480us,332us,40369us
  
  # 日志分析
  1,2022-07-11 10:26:59.499204   #日志打印时间
  2,undefined      # 逻辑租户名
  3,               # 逻辑库名
  4,obcluster:sys:test  # 物理库信息（cluster:tenant:database）
  5,OB_MYSQL  # 数据库类型
  6,SELECT    # SQL 类型
  7,success   # 执行结果（success/failed）
  8,          # 错误码（success 时为空）
  9,1         # 总请求数量
  10,1           # [30 ms, 100 ms) 请求数量
  11,0           # [100 ms, 500 ms) 请求数量
  12,0           # [500 ms,+∞) 请求数量
  13,41480us     # 执行总耗时（ms，包括内部 SQL 执行耗时）
  14,332us       # 预执行时间
  15,40369u      # 数据库执行时间
  

慢 SQL 请求日志

obproxy_slow.log 日志是慢 SQL 请求日志，记录执行时间大于参数 slow_query_time_threshold 阈值（默认 500ms）的请求。

• 日志格式

  日志打印时间,当前应用名,TraceId,RpcId,逻辑数据源名称,物理库信息(cluster:tenant:database),数据库类型(OB/RDS),逻辑表名,物理表名,SQL 命令,SQL 类型(CRUD),执行结果(success/failed),错误码(success 时为空),SQL,执行总耗时(ms),预执行时间,链接建立时间,数据库执行时间,当前线程名,系统穿透数据,穿透数据
  

  说明：

  • SQL 命令 显示为 COM_QUERY、COM_STMT_PREPARE 等。

  • 执行总耗时 包括内部 SQL 执行耗时。

  • 当前线程名 显示 ODP 的内部线程 ID。

  • 系统穿透数据 将显示系统灾备信息等。

• 日志示例

  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
  

对于慢 SQL，在 obproxy.log 中也会有记录，关键字是 Slow Query，obproxy.log 中记录的信息更加详细，如执行 SQL 语句 select sleep(3) from dual，搜索 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},   // 执行 SQL client IP
server_ip={11.xxx.xxx.53:33041}, // SQL 被路由到的目标 OBServer 节点
obproxy_client_port={100.xxx.xxx.179:52052},  // 和 OceanBase 数据库连接的客户端地址
server_trace_id=Y81100B7C0535-0005E3460FBBE3CD-0-0, // 目标 OBServer 节点中执行过程中的 trace id
route_type=ROUTE_TYPE_NONPARTITION_UNMERGE_LOCAL, // SQL 使用的路由策略
user_name=root,         // 用户名
tenant_name=sys,        // 租户名
cluster_name=obcluster,  // 集群名
logic_database_name=,  // 逻辑库名
logic_tenant_name=,    // 逻辑租户名
ob_proxy_protocol=0,   // 协议类型
cs_id=14,         // client login 时看到的 connection id, ODP 分配
proxy_sessid=7230691598940700681, // client 访问 OceanBase 时内部记录 connection id
ss_id=21, 
server_sessid=3221588238,  // SQL 在目标 OBServer 节点中的 connection id, OBServer 节点分配
sm_id=14, 
cmd_size_stats={
    client_request_bytes:20,  // client 发给 ODP 的请求包大小
    server_request_bytes:38,  // ODP 发给目标 OBServer 节点的请求包大小
    server_response_bytes:0,  // 目标 OBServer 节点发给 ODP 的响应包大小
    client_response_bytes:71}, // ODP 发给 client 的响应包大小
cmd_time_stats={
    client_transaction_idle_time_us=0, // 在事务中该条 SQL 与上一条 SQL 执行结束之间的间隔时间, 即 client 事务间隔时间
    client_request_read_time_us=97, // ODP 从 client socket 读取请求包的耗时
    client_request_analyze_time_us=95, // ODP 分析 client 的 SQL 耗时
    cluster_resource_create_time_us=0, // ODP 创建集群资源耗时(仅首次访问集群时需要创建)
    pl_lookup_time_us=0, // 根据 SQL 获取涉及路由表的耗时
    pl_process_time_us=0,  // 对涉及路由表的进行筛选排序的耗时
    congestion_control_time_us=21,  // 根据 SQL 获取涉及黑名单信息的耗时
    congestion_process_time_us=3,  // 对涉及黑名单的进行检查过滤的耗时
    do_observer_open_time_us=55,  // 对目标 OBServer 节点获取可用连接的耗时, 包含 connect_time
        server_connect_time_us=0,  // 对目标 OBServer 节点创建连接的耗时
    server_sync_session_variable_time_us=0,  // 对选择的目标连接进行初始化的耗时, 包括 saved_login, 同步 db, 同步系统变量, 同步 last_insert_id, 同步 start_trans
        server_send_saved_login_time_us=0,  // 对选择的目标连接进行 saved login 耗时
        server_send_use_database_time_us=0,  // 对选择的目标连接同步 db 耗时
        server_send_session_variable_time_us=0,  // 对选择的目标连接同步已修改的系统变量耗时
        server_send_all_session_variable_time_us=0,  // 对选择的目标连接同步所有系统耗时
        server_send_last_insert_id_time_us=0, // 对选择的目标连接同步 last_insert_id 耗时
        server_send_start_trans_time_us=0,   // 对选择的目标连接同步 start_trans/begin 耗时
    build_server_request_time_us=23,  // 构建对目标 Server 的请求包的耗时
    plugin_compress_request_time_us=0,   // 对请求包进行压缩耗时
    prepare_send_request_to_server_time_us=409,  // ODP 接受到客户端请求，到转发到 OBServer 节点执行前总计时间，正常应该是前面所有时间之和
    server_request_write_time_us=32,  // ODP 向目标 server socket 发送请求包的耗时
    server_process_request_time_us=3039883,   // 目标 Server 该执行 SQL 的耗时
    server_response_read_time_us=67,   // ODP 从目标 server socket 读取响应包的耗时
    plugin_decompress_response_time_us=59, // 对响应包进行解压缩耗时
    server_response_analyze_time_us=70,  // 对响应包进行分析的耗时
    ok_packet_trim_time_us=0, // 对响应包 trim 掉最后一个 ok 包的耗时
    client_response_write_time_us=185,  // ODP 向 client socket 发送响应包的耗时
    request_total_time_us=3041116},  // ODP 处理该请求总时间, 等于前面所有耗时之和
sql=select sleep(3)   //client 的请求 SQL
))

ODP 错误日志

obproxy_error.log 日志是 ODP 错误日志，执行错误的请求会打印到该日志中，包括 ODP 自身错误和 OceanBase 数据库返回错误。

• 日志格式

  日志打印时间,当前应用名,TraceId,RpcId,逻辑数据源名称,物理库信息(cluster:tenant:database),数据库类型(OB/RDS),逻辑表名,物理表名,SQL 命令,SQL 类型(CRUD),执行结果(success/failed),错误码(success 时为空),SQL,执行总耗时(ms),预执行时间,链接建立时间,数据库执行时间,当前线程名,系统穿透数据,穿透数据,错误详情
  

  说明：

  • SQL 命令 显示为 COM_QUERY、COM_STMT_PREPARE 等。

  • 执行总耗时 包括内部 SQL 执行耗时。

  • 当前线程名 显示 ODP 的内部线程 ID。

  • 系统穿透数据 将显示系统灾备信息等。

• 日志示例

  此处以 select obproxy_error from dual 命令做测试，其中 obproxy_error 字段没有加引号，会被当作列处理，导致执行失败。客户端报错如下

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

  打开 obproxy_error.log，内容如下：

  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'
  
  # 日志分析
  1,2022-07-11 10:26:09.358231    #日志打印时间
  2,undefined           # 无需关注，内部使用
  3,                    # 无需关注，内部使用
  4,                    # 无需关注，内部使用
  5,                    # 无需关注，内部使用
  6,obcluster:sys:test  # 物理库信息（cluster:tenant:database）
  7,OB_MYSQL         # 数据库类型
  8,                 # 逻辑表名
  9,                 # 物理表名
  10,COM_QUERY       # SQL 命令（COM_QUERY、COM_STMT_PREPARE 等）
  11,SELECT          # SQL 类型
  12,failed          # 执行结果（success/failed）
  13,1054            # 错误码（success 时为空）
  14,select obproxy_error from dual  # SQL 语句
  15,42423us         # 执行总耗时（ms，包括内部 SQL 执行耗时）
  16,454us           # 预执行时间
  17,0us             # 建立连接时间
  18,41222us         # 数据库执行时间
  19,Y0-7F4B1EF653A0 # ODP 内部日志 trace_id
  20,           # 无需关注，内部使用
  21,           # 无需关注，内部使用
  22,           # 无需关注，内部使用
  23,0          # 无需关注，内部使用
  24,11.xxx.xxx.53:33041  # 路由到的 OceanBase 数据库的地址信息
  25,Unknown column 'obproxy_error' in 'field list' # 报错信息
  

  从第 12 行可以看到执行失败，从第 24 行可以看到执行 SQL 的 OBServer 节点的地址信息，第 25 行有报错信息，就可以确定时数据库执行失败。

ODP 限流日志

obproxy_limit.log 日志是 ODP 限流日志，如果发生限流，被限流的请求将打印到该日志中。

• 日志格式

  日志打印时间,当前应用名,TraceId,RpcId,逻辑数据源名称,物理库信息(cluster:tenant:database),数据库类型(OB/RDS),逻辑表名,物理表名,SQL 命令(COM_QUERY、COM_STMT_PREPARE 等),SQL 类型(CRUD),限流状态(RUNNING/OBSERVE),SQL,限流规则名称
  

• 日志示例

  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

ODP 除了提供日志系统外，还提供 Prometheus 系统，以便对接不同的监控平台。Prometheus 系统提供总的请求数量、执行耗时、当前前端连接数、后端连接数等信息。具体监控项如下表所示：