ob日志查看技巧

OceanBase 技术问题
#1

ob日志有什么查看技巧吗？比如rootservice,observer的日志，后台日志打印是非常频繁的，怎么快速找到报错的内容？有的报错前面显示的还是INFO级别，而不是Error。

#3

以下面一条日志为例，介绍一下日志的组成。

[2021-06-11 16:30:02.372655] ERROR [BOOTSTRAP] bootstrap (ob_service.cpp:2656) [32075][428][YB420A27C94E-0005C47950223003] [lt=3] [dc=0] failed to prepare boot strap(rs_list=[region:"sys_region", zone:"z1", server:"127.0.0.1:2882", region:"sys_region", zone:"z2", server:"127.0.0.2:2882", region:"sys_region", zone:"z3", server:"127.0.0.3:2882"], ret=-4012) BACKTRACE:0x90a107e 0x90090c1 0x24d1eef 0x24d1b3b 0x24d1900 0x66678b1 0x882bb40 0x8912d74 0x91c24f8 0x8a5d45f 0x8a5d08d 0x8a5841f 0x8a5770d 0x8a57b17 0x2a55b14 0x8ebc475 0x8eb9e4e 0x8eb46ef
  • [2021-06-11 16:30:02.372655] 是时间戳。
  • ERROR是日志级别，还有INFO, WARN, TRACE, DEBUG等级别。
  • [BOOTSTRAP]是模块名称，其他模块还有SQL，STORAGE，COMMON等。
  • bootstrap是函数名。
  • ob_service.cpp:2656是文件名和行号。
  • [32075]是线程ID。
  • [428]是协程编号。
  • [YB420A27C94E-0005C47950223003]是trace_id，同一个请求会携带同一个trace_id。
  • [lt=3]是日志前端格式化时间，通常无意义（last log cost time us）。
  • [dc=0]无意义（async dropped log count）。
  • failed to prepare boot strap及后面是日志的具体内容。
  • ret=-4012表示错误码为-4012，-4012的语义是OB_TIMEOUT，可以通过ob_errno.h查询。
  • BACKTRACE是调用栈的地址，可以通过addr2line等工具解析函数的调用栈。
#4

ret=0 是表示成功没问题吧？我的想法是按照问题时间点截取日志，再搜索日志中ret不等于0的行，不知道是否可行，比如这个
[2024-07-17 10:57:54.407589] INFO [STORAGE] ob_storage.cpp:298 [1802597][0][YB420A1E3F46-00061D596B65F590-0-0] [lt=13] [dc=0] cannot get file length for not exist file(ret=-9011, uri=file:///data/nfs/test/ob_oracle/1717209395/incarnation_1/1001/data/backup_set_12_full_20240716/single_backup_set_info_@versionset@/@version@_9223372036854775807)
这条恢复的报错日志不属于ERROR级别，排查耗费了好长时间。

#5

是的，可以根据某些报错字段去过滤grep

#6

报错之后，通过在同一个 session 里立即执行（中间不要插入其他 SQL）

obclient> select last_trace_id();
+------------------------------------+
| last_trace_id()                    |
+------------------------------------+
| Y584A0B9E1F14-00060127094761B4-0-0 |
+------------------------------------+
1 row in set (0.00 sec)

拿到报错 SQL 对应的 trace id，然后拿着 trace id 捞日志。

grep Y584A0B9E1F14-00060127094761B0-0-0 observer.log*

示例详见这篇博客中的 “执行 DDL 捞不到有用的日志怎么办？” 部分。

1 个赞
#7

不能按照问题的时间点，要按照问题 SQL 对应的 trace id。

#8

这里不对的，根据错误码搜索日志，会漏掉日志里很多有用但不包含错误码的上下文，看下上面那篇博客吧~

1 个赞
#9

1、日志要结合上下文来看，有些日志报错前面显示的还是INFO级别，而不是Error 这种也会有；
2、如果你知道你出现问题的大概时间范围，比如start开始到end时间结束，那么你可以写一个shell脚本，从整个日志里面过滤出来发生问题时间范围的日志数据（缩小查的数据范围以及整成个excel可以打开的文件方便查看排序什么的）；
awk来处理，供参考脚本如下：

awk -v start="2024-03-17 10:51:32.241274" -v end="2024-03-17 10:51:39.317089" '{
    if (substr($0, 1, 1) == "[") {
        time_str = substr($0, 2, 26);
        if (match(time_str, /^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]{6}$/)) {
            if (time_str>start && time_str<=end){
                ret_value=0
                trace_id=""
                if (match($0, /ret=(-?[0-9]+)/)) {
                    ret_value = substr($0, RSTART + 4, RLENGTH - 4)
                }
                if ($6 ~ /^\[.*\]$/) {
                    gsub(/\[|\]/, ",", $6);  
                    n = split($6, a, ",");  
                    if(length(a)==7){
                        trace_id=a[6]
                    }
                }  
                # 行号,时间,日志等级,所属模块,文件:行号,ret值
                printf "%d,%s,%s,%s,%s,%s,%s\n", NR, time_str, $3, $4, $5,trace_id,ret_value
            }
        } else {
            #非时间开头的日志pass 或者额外处理
            pass
        }
    }
}' observer.log >extract_observer_start_end.csv

可以将符合的start开始到end时间结束数据抽取到extract_observer_start_end.csv,csv文件excel也可以快速看，中间有数据可能会遗漏，有行号可以回到原始日志定位；
3、缩短时间范围，其实还是要根据trace_id去查找所有的上下文信息进行分析，trace_id可以去gv$SQL_AUDIT根据sql文本串等信息去查到对应的值；
4、前面抽取的字段里面有ret的值，可以大概快速看看，最终还是结合上下文日志分析；
5、当然查询日志可以在ocp上面查询，ocp也提供日志搜索功能，提供你的时间范围以及搜索字符串特征；

3 个赞
#10

目前来看日志确实打的比较多，如果排查SQL优化类问题根据trace_id来搜日志是最直接的，如果是运维问题那没啥好的办法只能看下打印的ERROR信息关联的上下文，以及看看选举或者RS日志等