trace分析方法

trace 分析主要是针对格式化后的输出文件进行分析，本文档将介绍各个输出文件如何解读，并提供 trace 分析问题的方法。

输出文件解读

trace 格式化输出主要有两种类型：flow 和 format 。flow 输出包括后缀名为 version, flw, except, funcRecord.csv, error 的5个文件；format 输出包括后缀名为 version, fmt 的2个文件。下面具体介始各个文件的输出及各部分的具体含义。

  • 版本文件： 后缀名为 version，可以通过该文件了解引擎的版本号和 Release。
  • 流程文件： 后缀名为 flw，按线程执行流程进行组织输出，输出组成如下：
tid: 线程号
顺序号： 函数名 Entry|Exit [retCode=函数返回值]（行号）：时间戳 （时间间隔）

Note：

上面的 Entry 是在函数入口时才会显示，Exit 是在函数出口时才会显示，retCode=函数返回值也只在函数出口且有返回值时才显示，时间间隔只有在大于1ms的情况下才会显示。时间间隔的单位为微秒。

  • 异常文件：后缀名为 except，函数调用中，两处跟踪之间最大时间间隔大于3ms 时，该函数的跟踪记录会被输出到这个文件中。
函数名
sequence: 顺序号 tid: 线程号 cost: 函数自身的开销（最大时间间隔）
顺序号： 函数名 Entry|Exit [retCode=函数返回值]（行号）：时间戳 （时间间隔）

  • 汇总统计文件：后缀名为 funcRecord.csv，这个属于汇总性质的文件，其中每一行由如下几个部分组成：

    • 函数名
    • 被调用次数
    • 平均开销
    • 最小开销
    • 最大总的开销
    • 最大自身开销
    • 最大时间间隔 top 5 的跟踪记录，top 5跟踪记录的格式为: 顺序号，函数调用总的开销，函数调用自身的开销，最大时间间隔

    Note：

    函数自身的开销是把调用子函数的开销排除在外的，函数调用的总的开销是包含子函数调用的开销的，最大时间间隔一般是一个函数中最耗时的部分，所有开销的单位都微秒。

  • 错误文件：后缀名为 error，错误输出文件，主要是记录存在函数出口的跟踪记录，没有匹配到函数入口的跟踪记录。

  • 格式化文件： 后缀名为 fmt，按照 dump 出来的二进制文件直接格式化输出的结果，其中输出各部分如下表：

顺序号： 函数名 Entry
tid: 线程号， numArgs: 参数数量
arg*: 对应参数具体的值

结合 trace 分析问题

trace 可以用来分析两类问题，常规问题和性能问题。分析常规问题时，主要关注 flw 文件，找到最开始报错的函数结合代码进行分析。

示例

节点正常启动的情况下，创建集合空间报 -133 错误。

  • 用户通过协调节点的诊断日志确定报错的节点，并连接到该节点，按照 trace 的输出及格式化中的方法开启 trace 跟踪：
  1. var db = new Sdb("localhost:11820")
  2. db.traceOn(100)
  • 创建集合空间，报 -133，重现问题
  1. db.createCS('example')
  • 导出跟踪记录为二进制文件
  1. db.traceOff("dbpath/11820.dump")
  • 格式化输出
  1. traceFmt(0, 'dbpath/11820.dump', 'dbpath/11820')\
  • 打开11820.flw，找到最初报 -133 的位置：
  1. 14502:  | | | | | sdbCatalogueCB::getAGroupRand Entry(650): 2019-04-28-17.26.49.916397
  2. 14503:  | | | | | | sdbCatalogueCB::getAGroupRand(653): 2019-04-28-17.26.49.916397
  3. 14504:  | | | | | sdbCatalogueCB::getAGroupRand Exit[retCode=-133](689): 2019-04-28-17.26.49.916397
  4. 14505:  | | | | catCatalogueManager::_assignGroup Exit[retCode=-133](1057): 2019-04-28-17.26.49.916398
  5. 14506:  | | | | pdLog Entry(431): 2019-04-28-17.26.49.916398
  • 显示 sdbCatalogueCB::getAGroupRand 最开始报 -133，结合代码是由于 grpMapId 为空导致报错：
  1. INT32 sdbCatalogueCB::getAGroupRand( UINT32 &groupID )
  2. {
  3.    INT32 rc = SDB_CAT_NO_NODEGROUP_INFO ;
  4.    PD_TRACE_ENTRY ( SDB_CATALOGCB_GETAGROUPRAND ) ;
  5.    UINT32 mapSize = _grpIdMap.size();
  6.    PD_TRACE1 ( SDB_CATALOGCB_GETAGROUPRAND,
  7.                   PD_PACK_UINT ( mapSize ) ) ;
  8.    if ( mapSize > 0 )
  9.    {
  10.       ...
  11.    }
  12. done:
  13.    PD_TRACE_EXITRC ( SDB_CATALOGCB_GETAGROUPRAND, rc ) ;
  14.    return rc;
  15. }

  • 向 _grpIdMap 插入元素的方法是激活组，找到激活组的命令，确认客户端的操作激活组，定位到需要调用 group.start() 。

  • 分析性能问题，先通过 funcRecord.csv 文件找到执行次数( count )，平均开销( avgcost )或者是两者的乘积最大的跟踪记录。结合 except 找到该函数最耗时的部分定位到 flw 文件的调用栈进行分析。

  • 遇到一个操作长时间没有返回，可以通过会话快照找到执行当前操作的节点，连接到该节点并开启 trace：

  1. var db = new Sdb("localhost:11850")
  2. db.traceOn(100)
  • 等待一定时间，关闭 trace ，dump 跟踪记录为二进制文件：
  1. db.traceOff('dbpath/11850.dump')
  • 格式化输出
  1. traceFmt(0,"dbpath/11850.dump", "dbpath/11850")
  • 打开 funRecord.csv 文件，按照 count 或者 avgcost 或者 count * avgcost 列进行排序：
namecountavgcostminmaxIn2OutCostmaxCurrentCostfirstsecondthirdfourthfifth
dpsTransLockManager::testAcquire2494864.428464(695479,79,64,60)(810062,75,57,52)(453115,52,35,31)(1784951,44,32,26)(36851,29,24,23)
_ossRWMutex::lock_r1663290.401111(260534,11,11,11)(420358,11,11,11)(923134,11,11,11)(328570, 10, 10,10)(840320,10,10,10)
_ossRWMutex::release_r1663290.401111(1548679,11,11,11)(529485, 9, 9, 9)(918758, 9, 9, 9)(1351621, 9, 9, 9)(721985, 8, 8, 8)
dpsTransLockManager::_tryAcquireOrTest1663253.723634(940645, 36, 34,33)(281898,33,32,27)(23643, 30, 28,26)(450779, 26, 26,23)(603613,27,27,23)
_dmsStorageBase::_markHeaderInvalid180.2022(325029, 2, 2, 2)(1270007, 1, 1, 1)(325032, 0, 0, 0)(325034, 0, 0, 0)(325036, 0, 0, 0)

用户从调用次数最多的函数入手，找到最大时间间隔 top 5 中的 first 里面的顺序号810062。如果从最大耗时入手，应先关联 except 文件，找到耗时最大的调用点，从调用次数入手的会直接通过顺序号去关联 flw 文件。以下是通过顺序号关联 flw 的结果：

  1. 810062:  dpsTransLockManager::testAcquire Entry(2772): 2019-05-11-13.31.17.908202
  2. 810063:  | dpsTransLockManager::testAcquire(2781): 2019-05-11-13.31.17.908254
  3. 810064:  | dpsTransLockManager::testAcquire(2809): 2019-05-11-13.31.17.908258
  4. 810065:  | dpsTransLockManager::testAcquire Entry(2772): 2019-05-11-13.31.17.908259
  5. 810066:  | | dpsTransLockManager::testAcquire(2781): 2019-05-11-13.31.17.908261
  6. 810067:  | | dpsTransLockManager::testAcquire(2809): 2019-05-11-13.31.17.908263
  7. 810068:  | | dpsTransLockManager::testAcquire Entry(2772): 2019-05-11-13.31.17.908263
  8. 810069:  | | | dpsTransLockManager::testAcquire(2781): 2019-05-11-13.31.17.908265
  9. 810070:  | | | dpsTransLockManager::_tryAcquireOrTest Entry(1231): 2019-05-11-13.31.17.908266
  10. 810071:  | | | | dpsTransLockManager::_tryAcquireOrTest(1264): 2019-05-11-13.31.17.908267
  11. 810072:  | | | | _ossRWMutex::lock_r Entry(74): 2019-05-11-13.31.17.908268
  12. 810073:  | | | | _ossRWMutex::lock_r Exit(98): 2019-05-11-13.31.17.908269
  13. 810074:  | | | | _ossRWMutex::release_r Entry(166): 2019-05-11-13.31.17.908270
  14. 810075:  | | | | _ossRWMutex::release_r Exit(181): 2019-05-11-13.31.17.908270
  15. 810076:  | | | dpsTransLockManager::_tryAcquireOrTest Exit(1739): 2019-05-11-13.31.17.908270
  16. 810077:  | | dpsTransLockManager::testAcquire Exit(2836): 2019-05-11-13.31.17.908271
  17. 810078:  | | dpsTransLockManager::_tryAcquireOrTest Entry(1231): 2019-05-11-13.31.17.908271
  18. 810079:  | | | dpsTransLockManager::_tryAcquireOrTest(1264): 2019-05-11-13.31.17.908273
  19. 810080:  | | | _ossRWMutex::lock_r Entry(74): 2019-05-11-13.31.17.908274
  20. 810081:  | | | _ossRWMutex::lock_r Exit(98): 2019-05-11-13.31.17.908275
  21. 810082:  | | | _ossRWMutex::release_r Entry(166): 2019-05-11-13.31.17.908275
  22. 810083:  | | | _ossRWMutex::release_r Exit(181): 2019-05-11-13.31.17.908276
  23. 810084:  | | dpsTransLockManager::_tryAcquireOrTest Exit[retCode=-190](1739): 2019-05-11-13.31.17.908276
  24. 810085:  | dpsTransLockManager::testAcquire Exit[retCode=-190](2836): 2019-05-11-13.31.17.908277
  25. 810086:  dpsTransLockManager::testAcquire Exit[retCode=-190](2836): 2019-05-11-13.31.17.908277
  26. 810087:  dpsTransLockManager::testAcquire Entry(2772): 2019-05-11-13.31.17.908279
  27. 810088:  | dpsTransLockManager::testAcquire(2781): 2019-05-11-13.31.17.908281
  28. 810089:  | dpsTransLockManager::testAcquire(2809): 2019-05-11-13.31.17.908283
  29. 810090:  | dpsTransLockManager::testAcquire Entry(2772): 2019-05-11-13.31.17.908284
  30. 810091:  | | dpsTransLockManager::testAcquire(2781): 2019-05-11-13.31.17.908286
  31. 810092:  | | dpsTransLockManager::testAcquire(2809): 2019-05-11-13.31.17.908288
  32. 810093:  | | dpsTransLockManager::testAcquire Entry(2772): 2019-05-11-13.31.17.908288
  33. 810094:  | | | dpsTransLockManager::testAcquire(2781): 2019-05-11-13.31.17.908290
  34. 810095:  | | | dpsTransLockManager::_tryAcquireOrTest Entry(1231): 2019-05-11-13.31.17.908290
  35. 810096:  | | | | dpsTransLockManager::_tryAcquireOrTest(1264): 2019-05-11-13.31.17.908292
  36. 810097:  | | | | _ossRWMutex::lock_r Entry(74): 2019-05-11-13.31.17.908293
  37. 810098:  | | | | _ossRWMutex::lock_r Exit(98): 2019-05-11-13.31.17.908294
  38. 810099:  | | | | _ossRWMutex::release_r Entry(166): 2019-05-11-13.31.17.908294
  39. 810100:  | | | | _ossRWMutex::release_r Exit(181): 2019-05-11-13.31.17.908294
  40. 810101:  | | | dpsTransLockManager::_tryAcquireOrTest Exit(1739): 2019-05-11-13.31.17.908295
  41. 810102:  | | dpsTransLockManager::testAcquire Exit(2836): 2019-05-11-13.31.17.908295

通过该线程的调用栈，可以看到这个线程一直在重复调用 dpsTransLockManager::testAcquire, 原因是报 -190 导致一直在重试解决这个问题，解决了操作长时间不返回的问题。