1

我想使用 perf 工具解释我的程序的一个有趣行为。

一些背景资料

我的机器有 4 个 NUMA 节点,我的主要应用程序正在机器上运行。使用 cpusets 我对机器进行分区,为应用程序提供 3 个节点,为系统提供 1 个节点。在同一台机器上运行单元测试(用于记录改进)时,我得到了我正在尝试使用 perf 工具进行调查的意外行为。

出乎意料的行为是,在应用程序正在运行的 NUMA 节点上(比如说 node2),我在 unittest 上获得了更好的时间,大约是 unittest 在具有系统的 NUMA 节点上运行时的两倍(比如说节点 3)。看起来像在 node2 的 CPU 上运行(一个不做自旋锁的 cpu)我得到比在另一个 numa 上运行更好的结果。

我正在尝试改进我的日志记录系统,因此测试正在进行的工作也由应用程序完成,将一些日志消息写入队列以便稍后转储到磁盘(不同的线程)。对队列的争用由自旋锁 (CAS) 控制。unitest 是一个具有 2 个循环的写入器线程:100 次,将 1000 条日志写入队列,RDTSC(我的选择)用于测量每个内部循环,然后打印统计信息。队列足够大,我得到一个标准偏差,内存操作减少到最低限度(没有 memcpy)。阅读器正在转储到另一个线程上的磁盘。

我尝试停止我的应用程序并再次运行测试。在这种情况下,我看到无论选择哪个 NUMA 节点来运行我的测试,我都会得到与在 node3 上运行类似的结果(慢),这意味着如果我在同一个 numa 上运行我的测试,正在运行的应用程序正在加速我的测试应用程序运行的节点。对我来说非常不直观。

使用以下 perf 工具命令获取一些数据

rm /tmp/a; rm /tmp/ats; for f in $(perf list | tr -s ' ' | cut -d' ' -f 2 ); do perf stat -o /tmp/ats --append -e $f taskset -c $(cat /sys/devices/system/node/node2/cpulist) ./bin/testCore >> /tmp/a 2>&1;perf stat -o /tmp/ats --append -e $f taskset -c $(cat /sys/devices/system/node/node3/cpulist) ./bin/testCore >> /tmp/a 2>&1;done

并使用命令进行分析

cat /tmp/ats | grep -v "#" | grep -v "^ *$" | grep -v "seconds time elapsed\|Performance\|supported" | grep -v " 0 " | tr -s ' ' | tr -d ',' | awk '{if(knownEvent[$2]){if(((knownEvent[$2]/$1)<0.95) || ((knownEvent[$2]/$1)>1.05)){printf "diff:%s %.2f(%d/%d)\n",$2,(knownEvent[$2]/$1),knownEvent[$2],$1}}else{knownEvent[$2]=$1}}'| more
diff:branch-misses 1.08(470184/435284)
diff:bus-cycles 0.70(25570333/36774093)
diff:cpu-clock 0.69(191/276)
diff:L1-dcache-prefetch-misses 1.05(624172/593780)
diff:LLC-loads 0.92(665199/720197)
diff:LLC-load-misses 1.16(217684/187823)
diff:LLC-prefetches 0.87(193398/222148)
diff:LLC-prefetch-misses 0.85(98653/115483)
diff:dTLB-load-misses 1.09(195668/180291)
diff:dTLB-store-misses 1.11(39755/35910)
diff:scsi:scsi_dispatch_cmd_start 1.38(11/8)
diff:block:block_rq_insert 0.58(36/62)
diff:block:block_rq_issue 1.50(12/8)
diff:block:block_bio_backmerge 1.05(683/650)
diff:block:block_getrq 0.57(36/63)
diff:block:block_plug 0.52(26/50)
diff:kmem:mm_pagevec_free 1.06(16853/15838)
diff:kmem:mm_kernel_pagefault 0.88(7/8)
diff:timer:timer_start 0.36(21/59)
diff:timer:timer_expire_entry 3.00(3/1)
diff:timer:timer_expire_exit 2.00(2/1)
diff:timer:timer_cancel 1.60(8/5)
diff:timer:hrtimer_start 0.93(1275/1368)
diff:timer:hrtimer_expire_entry 0.72(186/259)
diff:timer:hrtimer_expire_exit 0.69(182/264)
diff:timer:hrtimer_cancel 0.74(192/259)
diff:irq:softirq_entry 0.64(374/585)
diff:irq:softirq_exit 0.74(394/536)
diff:irq:softirq_raise 0.73(390/531)
diff:sched:sched_wakeup 0.75(3/4)
diff:sched:sched_stat_wait 0.50(1/2)
diff:sched:sched_stat_sleep 2.00(2/1)
diff:sched:sched_stat_runtime 0.93(1284/1379)

我提取了我看到的包含一些差异的内容。 不确定我是否应该怀疑 sched-、LLC-、branch-、TLB,因为我不知道相对差异是否解释了我看到的行为。

有什么更好的调查方法的建议吗?

4

0 回答 0