sitemap

RSS地图

收藏本站

设为首页

Oracle研究中心

当前位置:Oracle研究中心 > 产品DBA > Oracle ASM >

【学习笔记】Oracle 10g rac如何通过votedisk来判断disk心跳

时间:2016-12-16 11:03   来源:Oracle研究中心   作者:网络   点击:

天萃荷净 Oracle研究中心学习笔记:分享一篇关于Oracle数据库RAC的文章,详细介绍了Oracle 10g rac如何通过votedisk来判断disk心跳。

本站文章除注明转载外,均为本站原创: 转载自love wife & love life —Roger 的Oracle技术博客
本文链接地址: 10g rac如何通过votedisk来判断disk心跳?(2)

前不久写了一篇关于votedisk 心跳的文章,后面稍有疑问,那就是votedisk是在什么情况才会被写入的?

从前面的研究我们可以看到,正常情况下,ocssd进程是不会写votedisk的,仅仅是读,通过每秒读1次来判断disk 心跳是否正常。 这里我来模拟rac 脑裂的情况,通过手工断开rac2节点的心跳网卡,在断开之前
同事跟踪rac1,和rac2节点的ocssd进程,trace 信息如下:


---rac2

[root@rac2 tmp]# cat trc.log |grep write
18385      0.000041 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18418      0.000031 write(17, "t\0\0\0\3\0\0\0\n\2\1\4e\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000038 <... write resumed> ) = 116
18418      0.000030 write(25, "H\0\0\0\26\0\0\0\n\2\1\1a\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000028 <... write resumed> ) = 72
18385      0.000058 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18369      0.000013 write(8, "[    CSSD]2012-11-22 01:18:10.72"..., 110
18418      0.000019 write(17, "t\0\0\0\3\0\0\0\n\2\1\4f\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000022 <... write resumed> ) = 116
18418      0.000018 write(25, "H\0\0\0\26\0\0\0\n\2\1\1b\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000024 <... write resumed> ) = 72
18369      0.009731 <... write resumed> ) = 110
18369      0.000047 write(8, "[    CSSD]2012-11-22 01:18:10.72"..., 110) = 110
18385      0.000039 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18418      0.000030 write(17, "t\0\0\0\3\0\0\0\n\2\1\4g\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000042 <... write resumed> ) = 116
18418      0.000031 write(25, "H\0\0\0\26\0\0\0\n\2\1\1c\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000026 <... write resumed> ) = 72
18385      0.000057 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18369      0.000018 write(8, "[    CSSD]2012-11-22 01:18:12.72"..., 151
18369      0.001543 <... write resumed> ) = 151
18369      0.000072 write(8, "[    CSSD]2012-11-22 01:18:12.72"..., 135
18369      0.000016 <... write resumed> ) = 135
18369      0.000024 write(8, "[    CSSD]2012-11-22 01:18:12.72"..., 160
18369      0.001564 <... write resumed> ) = 160
18369      0.000044 write(8, "[    CSSD]2012-11-22 01:18:12.72"..., 176) = 176
18369      0.003378 write(8, "[    CSSD]2012-11-22 01:18:12.73"..., 151) = 151
18369      0.003270 write(8, "[    CSSD]2012-11-22 01:18:12.73"..., 133) = 133
18369      0.003225 write(8, "[    CSSD]2012-11-22 01:18:12.73"..., 165) = 165
18418      0.000037 write(17, "t\0\0\0\3\0\0\0\n\2\1\4h\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000041 <... write resumed> ) = 116
18418      0.000095 write(25, "H\0\0\0\26\0\0\0\n\2\1\1d\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000032 <... write resumed> ) = 72
18385      0.000142 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18418      0.000030 write(17, "t\0\0\0\3\0\0\0\n\2\1\4i\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000034 <... write resumed> ) = 116
18418      0.000031 write(25, "H\0\0\0\26\0\0\0\n\2\1\1e\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000025 <... write resumed> ) = 72
18385      0.000026 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18369      0.000010 write(8, "[    CSSD]2012-11-22 01:18:15.61"..., 110
18418      0.000024 write(17, "t\0\0\0\3\0\0\0\n\2\1\4j\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000039 <... write resumed> ) = 116
18369      0.000016 <... write resumed> ) = 110
18369      0.000017 write(8, "[    CSSD]2012-11-22 01:18:15.61"..., 110
18418      0.000022 write(25, "H\0\0\0\26\0\0\0\n\2\1\1f\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000020 <... write resumed> ) = 72
18369      0.002038 <... write resumed> ) = 110
18385      0.000024 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18418      0.000013 write(17, "t\0\0\0\3\0\0\0\n\2\1\4k\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000015 <... write resumed> ) = 116
18418      0.000014 write(25, "H\0\0\0\26\0\0\0\n\2\1\1g\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000030 <... write resumed> ) = 72
18385      0.000047 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18418      0.000018 write(17, "t\0\0\0\3\0\0\0\n\2\1\4l\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000020 <... write resumed> ) = 116
18418      0.000019 write(25, "H\0\0\0\26\0\0\0\n\2\1\1h\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000015 <... write resumed> ) = 72
18369      0.000010 write(8, "[    CSSD]2012-11-22 01:18:18.40"..., 151
18369      0.003419 <... write resumed> ) = 151
18369      0.000044 write(8, "[    CSSD]2012-11-22 01:18:18.40"..., 135
18369      0.000040 <... write resumed> ) = 135
18369      0.000014 write(8, "[    CSSD]2012-11-22 01:18:18.40"..., 160
18369      0.002043 <... write resumed> ) = 160
18369      0.000040 write(8, "[    CSSD]2012-11-22 01:18:18.40"..., 176) = 176
18369      0.003584 write(8, "[    CSSD]2012-11-22 01:18:18.41"..., 151) = 151
18369      0.003134 write(8, "[    CSSD]2012-11-22 01:18:18.41"..., 133) = 133
18369      0.003331 write(8, "[    CSSD]2012-11-22 01:18:18.41"..., 165) = 165
18385      0.000055 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18418      0.000033 write(17, "t\0\0\0\3\0\0\0\n\2\1\4m\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000035 <... write resumed> ) = 116
18418      0.000031 write(25, "H\0\0\0\26\0\0\0\n\2\1\1i\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000039 <... write resumed> ) = 72
18385      0.000068 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18369      0.000023 write(8, "[    CSSD]2012-11-22 01:18:20.59"..., 110
18418      0.000031 write(17, "t\0\0\0\3\0\0\0\n\2\1\4n\16\0\0\0\0\0\0\1\0\0\0\10\212W\1\0\0\0\0"..., 116
18418      0.000146 <... write resumed> ) = 116
18369      0.000017 <... write resumed> ) = 110
18369      0.000028 write(8, "[    CSSD]2012-11-22 01:18:20.59"..., 110
18369      0.000038 <... write resumed> ) = 110
18418      0.000037 write(25, "H\0\0\0\26\0\0\0\n\2\1\1j\16\0\0\0\0\0\0\2\0\0\0\326\216W\1\0\0\0\0"..., 72
18418      0.000027 <... write resumed> ) = 72
18385      0.000060 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18406      0.000029 write(42, "0\0\0\0\1\0\1\0\1\0\1\0\1\0\0\0\0\0\0\0\1\0\0\0\266\363\217\1\0\0\0\0"..., 48) = 48
18369      0.000024 write(8, "[    CSSD]2012-11-22 01:18:21.44"..., 95
18414      0.000023 write(42, "~\0\0\0\1\0\2\0\1\1\1\1\2\0\0\0\0\0\0\0\1\0\0\0\266\363\217\1\0\0\0\0"..., 126
18414      0.000011 <... write resumed> ) = 126
18369      0.000011 <... write resumed> ) = 95
18369      0.000051 write(8, "[    CSSD]2012-11-22 01:18:21.44"..., 90
18414      0.000014 write(42, "8\0\0\0\3\0\2\0\1\1\1\1\3\0\0\0\0\0\0\0\1\0\0\0\266\363\217\1\0\0\0\0"..., 56
18414      0.000012 <... write resumed> ) = 56
18369      0.000008 <... write resumed> ) = 90
18406      0.000043 write(42, "<\0\0\0\17\0\0\0\n\2\1\1\4\0\0\0\0\0\0\0\1\0\0\0\266\363\217\1\0\0\0\0"..., 60) = 60
18369      0.000009 write(8, "[    CSSD]2012-11-22 01:18:21.45"..., 146
18369      0.002821 <... write resumed> ) = 146
18369      0.000010 write(8, "[    CSSD]2012-11-22 01:18:21.45"..., 118
18406      0.000010 write(24, "\240\1\0\0\3\0\0\0\n\3\1\2\251\5\0\0\0\0\0\0\1\0\0\0h\216W\1\0\0\0\0"..., 416
18406      0.000013 <... write resumed> ) = 416
18416      0.000014 write(42, "\204\0\0\0\2\0\1\1\n\2\1\1\1\0\0\0\0\0\0\0\2\0\0\0\266\363\217\1\0\0\0\0"..., 132
18416      0.000011 <... write resumed> ) = 132
18369      0.000009 <... write resumed> ) = 118
18369      0.000015 write(8, "[    CSSD]2012-11-22 01:18:21.45"..., 124
18416      0.000019 write(42, "\24\2\0\0\6\0\0\0\n\2\1\1\2\0\0\0\0\0\0\0\2\0\0\0\266\363\217\1\0\0\0\0"..., 532
18416      0.000013 <... write resumed> ) = 532
18369      0.001353 <... write resumed> ) = 124
18369      0.000036 write(8, "[    CSSD]2012-11-22 01:18:21.45"..., 165) = 165
18369      0.003164 write(8, "[    CSSD]2012-11-22 01:18:21.45"..., 129
18406      0.000010 write(24, "X\1\0\0\4\0\0\0\n\3\1\2\252\5\0\0\0\0\0\0\1\0\0\0h\216W\1\0\0\0\0"..., 344
18406      0.000014 <... write resumed> ) = 344
18369      0.000067 <... write resumed> ) = 129
18369      0.000012 write(8, "[    CSSD]2012-11-22 01:18:21.45"..., 110
18416      0.000014 write(42, "8\0\0\0\7\0\0\0\n\2\1\1\3\0\0\0\0\0\0\0\2\0\0\0\266\363\217\1\0\0\0\0"..., 56
18416      0.000012 <... write resumed> ) = 56
18369      0.001702 <... write resumed> ) = 110
18369      0.000085 write(8, "[    CSSD]2012-11-22 01:18:21.45"..., 119) = 119
........省略部分信息

最后再过滤一下,只留pwrite64的信息:

[root@rac2 tmp]# cat trc.log |grep pwrite64
18385      0.000041 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
......省略部分信息
18385      0.000065 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18385      0.000049 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216
18385      0.000211 <... pwrite64 resumed> ) = 512
18385      0.000059 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
18385      0.000026 pwrite64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216
18385      0.000497 <... pwrite64 resumed> ) = 512

从上面可以看到,在脑裂发生时,会将512 bytes的信息写入到votedisk中,然后其他节点在读取votedisk时就能够知道该node的状态等信息,进而发出node 驱逐的命令。

通过fd下面的信息,可以可以确认fd 11/12都是votedisk,如下:

lr-x------ 1 oracle oinstall 64 Nov 22 01:24 0 -> /dev/null
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 9 -> socket:[189115]
l-wx------ 1 oracle oinstall 64 Nov 22 01:24 8 -> /home/oracle/app/oracle/product/10.2.0/crs/log/rac1/cssd/ocssd.log
lr-x------ 1 oracle oinstall 64 Nov 22 01:24 7 -> /home/oracle/app/oracle/product/10.2.0/crs/css/mesg/clssus.msb
lr-x------ 1 oracle oinstall 64 Nov 22 01:24 6 -> /dev/raw/raw1
lr-x------ 1 oracle oinstall 64 Nov 22 01:24 5 -> /dev/raw/raw3
lr-x------ 1 oracle oinstall 64 Nov 22 01:24 4 -> /home/oracle/app/oracle/product/10.2.0/crs/srvm/mesg/procus.msb
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 35 -> socket:[190069]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 34 -> socket:[189972]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 33 -> socket:[190254]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 32 -> socket:[189919]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 31 -> socket:[189899]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 30 -> socket:[189768]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 3 -> /home/oracle/app/oracle/product/10.2.0/crs/log/rac1/cssd/cssdOUT.log
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 29 -> socket:[190285]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 28 -> socket:[215569]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 27 -> socket:[189541]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 26 -> socket:[189538]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 25 -> socket:[189337]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 24 -> socket:[189336]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 23 -> socket:[189305]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 22 -> socket:[189304]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 21 -> socket:[189301]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 20 -> socket:[189299]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 2 -> /home/oracle/app/oracle/product/10.2.0/crs/log/rac1/cssd/cssdOUT.log
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 19 -> socket:[189297]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 18 -> socket:[189296]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 17 -> socket:[189335]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 16 -> socket:[189294]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 15 -> socket:[189291]
lr-x------ 1 oracle oinstall 64 Nov 22 01:24 14 -> /home/oracle/app/oracle/product/10.2.0/crs/has/mesg/clsdus.msb
l-wx------ 1 oracle oinstall 64 Nov 22 01:24 13 -> /home/oracle/app/oracle/product/10.2.0/crs/log/rac1/alertrac1.log
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 12 -> /dev/raw/raw2
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 11 -> /dev/raw/raw2
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 10 -> socket:[189116]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 1 -> /home/oracle/app/oracle/product/10.2.0/crs/log/rac1/cssd/cssdOUT.log
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 45 -> socket:[191987]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 44 -> socket:[215813]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 43 -> socket:[191911]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 42 -> socket:[191962]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 41 -> socket:[191834]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 40 -> socket:[191752]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 39 -> socket:[191708]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 38 -> socket:[191689]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 37 -> socket:[191507]
lrwx------ 1 oracle oinstall 64 Nov 22 01:24 36 -> socket:[190406]

然后,事实上,在脑裂发生的时刻,不仅仅是故障节点会讲node信息写入到votedisk中,其实其他节点也会写入信息,如下是rac2节点出现脑裂时,rac1节点 ocssd进程写votedisk的一个时间段:

---rac1:
17639      0.000093 pwrite64(11, "etoV\1\0\0\0\1\3\n\2\0\0\0\0rac1\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 8704) = 512
17639      0.000890 times(NULL)         = 432110519
17639      0.000088 gettimeofday({1353575942, 664201}, NULL) = 0
17639      0.000060 clock_gettime(CLOCK_REALTIME, {1353575942, 664263115}) = 0
17639      0.000061 futex(0x87299fc, FUTEX_WAIT_PRIVATE, 7477, {0, 999937885}
17665      0.020451 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17665      0.000063 times(NULL)         = 432110521
17665      0.000059 futex(0x862dea8, FUTEX_WAKE_PRIVATE, 1) = 0
17665      0.000051 times(NULL)         = 432110521
17665      0.000054 gettimeofday({1353575942, 685001}, NULL) = 0
17665      0.000085 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39032) = 1
17623      0.000054 <... futex resumed> ) = 0
17665      0.000090 times(
17623      0.000026 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17665      0.000048 <... times resumed> NULL) = 432110521
17623      0.000025 <... futex resumed> ) = 0
17665      0.000028 gettimeofday(
17623      0.000026 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39033, NULL
17665      0.000025 <... gettimeofday resumed> {1353575942, 685356}, NULL) = 0
17665      0.000053 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39034) = 1
17623      0.000049 <... futex resumed> ) = 0
17665      0.000028 times(
17623      0.000026 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17665      0.000025 <... times resumed> NULL) = 432110521
17623      0.000022 <... futex resumed> ) = 0
17665      0.000028 gettimeofday(
17623      0.000279 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39035, NULL
17665      0.000034 <... gettimeofday resumed> {1353575942, 685885}, NULL) = 0
17665      0.000040 clock_gettime(CLOCK_REALTIME, {1353575942, 685993707}) = 0
17665      0.000061 futex(0x862df34, FUTEX_WAIT_PRIVATE, 7501, {0, 999891293}
17654      0.264779 <... nanosleep resumed> NULL) = 0
17654      0.000099 times(NULL)         = 432110543
17654      0.000082 nanosleep({0, 170000000}, 
17666      0.039870 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17666      0.000104 times(NULL)         = 432110546
17666      0.000092 futex(0x862dfb8, FUTEX_WAKE_PRIVATE, 1) = 0
17666      0.000133 gettimeofday({1353575942, 991225}, NULL) = 0
17666      0.000101 times(NULL)         = 432110546
17666      0.000092 times(NULL)         = 432110546
17666      0.000078 gettimeofday({1353575942, 991487}, NULL) = 0
17666      0.000080 times(NULL)         = 432110546
17666      0.000070 times(NULL)         = 432110546
17666      0.000185 times(NULL)         = 432110546
17666      0.000098 sendto(15, "P", 1, 0, {sa_family=AF_INET, sin_port=htons(11992), sin_addr=inet_addr("127.0.0.1")}, 16) = 1
17658      0.000158 <... poll resumed> ) = 1 ([{fd=15, revents=POLLIN|POLLRDNORM}])
17666      0.000080 times(
17658      0.000106 read(15, 
17666      0.000051 <... times resumed> NULL) = 432110546
17658      0.000035 <... read resumed> "P", 2000) = 1
17666      0.000061 gettimeofday(
17658      0.000030 times(
17666      0.000035 <... gettimeofday resumed> {1353575942, 992411}, NULL) = 0
17658      0.000039 <... times resumed> NULL) = 432110546
17666      0.000045 clock_gettime(CLOCK_REALTIME, 
17658      0.000032 times(
17666      0.000035 <... clock_gettime resumed> {1353575942, 992562564}) = 0
17658      0.000037 <... times resumed> NULL) = 432110546
17666      0.000152 futex(0x872ac74, FUTEX_WAIT_PRIVATE, 14925, {0, 1848436}
17658      0.000052 futex(0x872ac74, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x872ab60, 14926
17666      0.000042 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17658      0.000038 <... futex resumed> ) = 0
17666      0.000051 futex(0x872ab60, FUTEX_WAIT_PRIVATE, 2, NULL
17658      0.000041 futex(0x872ab60, FUTEX_WAKE_PRIVATE, 1
17666      0.000038 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17658      0.000036 <... futex resumed> ) = 0
17666      0.000091 futex(0x872ac70, FUTEX_WAIT_PRIVATE, 2, NULL
17658      0.000049 futex(0x872ac70, FUTEX_WAKE_PRIVATE, 1
17666      0.000039 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17658      0.000035 <... futex resumed> ) = 0
17666      0.000048 futex(0x872ac70, FUTEX_WAKE_PRIVATE, 1
17658      0.000039 futex(0x872ac74, FUTEX_WAIT_PRIVATE, 14927, NULL
17666      0.000038 <... futex resumed> ) = 0
17658      0.000030 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17666      0.000052 futex(0x872ac74, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x872ab60, 14928
17658      0.000074 futex(0x872ab60, FUTEX_WAIT_PRIVATE, 2, NULL
17666      0.000038 <... futex resumed> ) = 0
17666      0.000114 times(NULL)         = 432110546
17666      0.000090 futex(0x872ab60, FUTEX_WAKE_PRIVATE, 1) = 1
17658      0.000084 <... futex resumed> ) = 0
17666      0.000047 write(26, "t\0\0\0\3\0\0\0\n\2\1\4\224\16\0\0\0\0\0\0\1\0\0\0.\336U\1\0\0\0\0"..., 116
17658      0.000102 futex(0x872ab60, FUTEX_WAKE_PRIVATE, 1
17666      0.000039 <... write resumed> ) = 116
17658      0.000088 <... futex resumed> ) = 0
17666      0.000055 times(
17658      0.000031 gettimeofday(
17666      0.000035 <... times resumed> NULL) = 432110546
17658      0.000038 <... gettimeofday resumed> {1353575942, 994296}, NULL) = 0
17666      0.000060 times(
17658      0.000028 times(
17666      0.000035 <... times resumed> NULL) = 432110546
17658      0.000046 <... times resumed> NULL) = 432110546
17666      0.000051 gettimeofday(
17658      0.000032 poll([{fd=15, events=POLLIN|POLLRDNORM}, {fd=16, events=POLLIN|POLLRDNORM}, {fd=26, events=POLLIN|POLLRDNORM}], 3, -1
17666      0.000571 <... gettimeofday resumed> {1353575942, 994589}, NULL) = 0
17666      0.000087 times(NULL)         = 432110546
17666      0.000075 times(NULL)         = 432110546
17666      0.000070 times(NULL)         = 432110546
17666      0.000089 sendto(18, "P", 1, 0, {sa_family=AF_INET, sin_port=htons(40479), sin_addr=inet_addr("127.0.0.1")}, 16) = 1
17660      0.000234 <... poll resumed> ) = 1 ([{fd=18, revents=POLLIN|POLLRDNORM}])
17666      0.000248 times(
17660      0.000033 read(18, 
17666      0.000044 <... times resumed> NULL) = 432110546
17660      0.000034 <... read resumed> "P", 2000) = 1
17666      0.000121 gettimeofday(
17660      0.000040 times(
17666      0.000035 <... gettimeofday resumed> {1353575942, 996237}, NULL) = 0
17660      0.000042 <... times resumed> NULL) = 432110546
17666      0.000046 clock_gettime(CLOCK_REALTIME, 
17660      0.000031 times(
17666      0.000035 <... clock_gettime resumed> {1353575942, 996392349}) = 0
17660      0.000036 <... times resumed> NULL) = 432110546
17666      0.000051 futex(0x87a6e94, FUTEX_WAIT_PRIVATE, 17857, {0, 1844651}
17660      0.000049 futex(0x87a6e94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x87a50c8, 17858
17666      0.000041 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17660      0.000106 <... futex resumed> ) = 0
17666      0.000055 futex(0x87a50c8, FUTEX_WAIT_PRIVATE, 2, NULL
17660      0.000042 futex(0x87a50c8, FUTEX_WAKE_PRIVATE, 1
17666      0.000038 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17660      0.000037 <... futex resumed> ) = 0
17666      0.000050 futex(0x87a6e90, FUTEX_WAIT_PRIVATE, 2, NULL
17660      0.000040 futex(0x87a6e90, FUTEX_WAKE_PRIVATE, 1
17666      0.000037 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17660      0.000034 <... futex resumed> ) = 0
17666      0.000049 futex(0x87a6e90, FUTEX_WAKE_PRIVATE, 1
17660      0.000102 futex(0x87a6e94, FUTEX_WAIT_PRIVATE, 17859, NULL
17666      0.000053 <... futex resumed> ) = 0
17660      0.000030 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17666      0.000053 futex(0x87a6e94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x87a50c8, 17860
17660      0.000042 futex(0x87a50c8, FUTEX_WAIT_PRIVATE, 2, NULL
17666      0.000036 <... futex resumed> ) = 0
17666      0.000040 times(NULL)         = 432110546
17666      0.000082 futex(0x87a50c8, FUTEX_WAKE_PRIVATE, 1) = 1
17660      0.000079 <... futex resumed> ) = 0
17666      0.000114 write(17, "H\0\0\0\26\0\0\0\n\2\1\1\235\16\0\0\0\0\0\0\2\0\0\0\274\264U\1\0\0\0\0"..., 72
17660      0.000132 futex(0x87a50c8, FUTEX_WAKE_PRIVATE, 1
17666      0.000040 <... write resumed> ) = 72
17660      0.000051 <... futex resumed> ) = 0
17666      0.000048 gettimeofday(
17660      0.000031 gettimeofday(
17666      0.000035 <... gettimeofday resumed> {1353575942, 998024}, NULL) = 0
17660      0.000107 <... gettimeofday resumed> {1353575942, 998054}, NULL) = 0
17666      0.000078 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39036
17660      0.000040 times(
17666      0.000037 <... futex resumed> ) = 1
17660      0.000034 <... times resumed> NULL) = 432110546
17623      0.000035 <... futex resumed> ) = 0
17666      0.000045 times(
17660      0.000032 poll([{fd=18, events=POLLIN|POLLRDNORM}, {fd=19, events=POLLIN|POLLRDNORM}, {fd=20, events=POLLIN|POLLRDNORM}, {fd=21, events=POLLIN|POLLRDNORM}, {fd=17, events=POLLIN|POLLRDNORM}, {fd=24, events=POLLIN|POLLRDNORM}, {fd=25, events=POLLIN|POLLRDNORM}, {fd=-1}, {fd=29, events=POLLIN|POLLRDNORM}, {fd=30, events=POLLIN|POLLRDNORM}, {fd=31, events=POLLIN|POLLRDNORM}, {fd=32, events=POLLIN|POLLRDNORM}, {fd=33, events=POLLIN|POLLRDNORM}, {fd=34, events=POLLIN|POLLRDNORM}, {fd=35, events=POLLIN|POLLRDNORM}, {fd=36, events=POLLIN|POLLRDNORM}, {fd=37, events=POLLIN|POLLRDNORM}, {fd=38, events=POLLIN|POLLRDNORM}, {fd=39, events=POLLIN|POLLRDNORM}, {fd=40, events=POLLIN|POLLRDNORM}, {fd=41, events=POLLIN|POLLRDNORM}, {fd=42, events=POLLIN|POLLRDNORM}, {fd=43, events=POLLIN|POLLRDNORM}, {fd=28, events=POLLIN|POLLRDNORM}, {fd=45, events=POLLIN|POLLRDNORM}], 25, -1
17623      0.000389 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17666      0.000043 <... times resumed> NULL) = 432110546
17623      0.000035 <... futex resumed> ) = 0
17666      0.000042 gettimeofday(
17623      0.000038 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39037, NULL
17666      0.000036 <... gettimeofday resumed> {1353575942, 999007}, NULL) = 0
17666      0.000049 clock_gettime(CLOCK_REALTIME, {1353575942, 999130873}) = 0
17666      0.000131 futex(0x862e044, FUTEX_WAIT_PRIVATE, 7487, {0, 999876127}
17654      0.124637 <... nanosleep resumed> NULL) = 0
17654      0.000073 times(NULL)         = 432110556
17654      0.000055 nanosleep({0, 40000000}, 
17660      0.015093 <... poll resumed> ) = 1 ([{fd=28, revents=POLLIN|POLLRDNORM}])
17660      0.000252 times(NULL)         = 432110558
17660      0.000057 times(NULL)         = 432110558
17660      0.000064 read(28, "0\0\0\0\2\0\20\0\1\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0@\312\216\1\0\0\0\0"..., 32768) = 48
17660      0.000103 gettimeofday({1353575943, 139591}, NULL) = 0
17660      0.000061 times(NULL)         = 432110558
17660      0.000145 times(NULL)         = 432110558
17660      0.000047 times(NULL)         = 432110558
17660      0.000055 times(NULL)         = 432110558
17660      0.000047 times(NULL)         = 432110558
17660      0.000047 times(NULL)         = 432110558
17660      0.000105 gettimeofday({1353575943, 140099}, NULL) = 0
17660      0.000107 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39038) = 1
17623      0.000066 <... futex resumed> ) = 0
17660      0.000032 times(
17623      0.000025 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17660      0.000027 <... times resumed> NULL) = 432110558
17623      0.000024 <... futex resumed> ) = 0
17660      0.000044 gettimeofday(
17623      0.000023 write(8, "[    CSSD]2012-11-22 01:19:03.14"..., 87
17660      0.000379 <... gettimeofday resumed> {1353575943, 140423}, NULL) = 0
17660      0.000090 fcntl64(28, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
17660      0.000133 fcntl64(28, F_SETFL, O_RDWR) = 0
17660      0.000219 close(28)           = 0
17660      0.000080 gettimeofday({1353575943, 141348}, NULL) = 0
17660      0.000076 gettimeofday({1353575943, 141444}, NULL) = 0
17660      0.000113 gettimeofday({1353575943, 141536}, NULL) = 0
17660      0.000058 times(NULL)         = 432110558
17660      0.000052 poll([{fd=18, events=POLLIN|POLLRDNORM}, {fd=19, events=POLLIN|POLLRDNORM}, {fd=20, events=POLLIN|POLLRDNORM}, {fd=21, events=POLLIN|POLLRDNORM}, {fd=17, events=POLLIN|POLLRDNORM}, {fd=24, events=POLLIN|POLLRDNORM}, {fd=25, events=POLLIN|POLLRDNORM}, {fd=-1}, {fd=29, events=POLLIN|POLLRDNORM}, {fd=30, events=POLLIN|POLLRDNORM}, {fd=31, events=POLLIN|POLLRDNORM}, {fd=32, events=POLLIN|POLLRDNORM}, {fd=33, events=POLLIN|POLLRDNORM}, {fd=34, events=POLLIN|POLLRDNORM}, {fd=35, events=POLLIN|POLLRDNORM}, {fd=36, events=POLLIN|POLLRDNORM}, {fd=37, events=POLLIN|POLLRDNORM}, {fd=38, events=POLLIN|POLLRDNORM}, {fd=39, events=POLLIN|POLLRDNORM}, {fd=40, events=POLLIN|POLLRDNORM}, {fd=41, events=POLLIN|POLLRDNORM}, {fd=42, events=POLLIN|POLLRDNORM}, {fd=43, events=POLLIN|POLLRDNORM}, {fd=-1}, {fd=45, events=POLLIN|POLLRDNORM}], 25, 0) = 0 (Timeout)
17660      0.000716 times(NULL)         = 432110558
17660      0.000050 times(NULL)         = 432110558
17660      0.000049 times(NULL)         = 432110558
17660      0.000047 times(NULL)         = 432110558
17660      0.000047 times(NULL)         = 432110558
17660      0.000071 gettimeofday({1353575943, 142625}, NULL) = 0
17660      0.000405 times(NULL)         = 432110558
17660      0.000066 poll([{fd=18, events=POLLIN|POLLRDNORM}, {fd=19, events=POLLIN|POLLRDNORM}, {fd=20, events=POLLIN|POLLRDNORM}, {fd=21, events=POLLIN|POLLRDNORM}, {fd=17, events=POLLIN|POLLRDNORM}, {fd=24, events=POLLIN|POLLRDNORM}, {fd=25, events=POLLIN|POLLRDNORM}, {fd=-1}, {fd=29, events=POLLIN|POLLRDNORM}, {fd=30, events=POLLIN|POLLRDNORM}, {fd=31, events=POLLIN|POLLRDNORM}, {fd=32, events=POLLIN|POLLRDNORM}, {fd=33, events=POLLIN|POLLRDNORM}, {fd=34, events=POLLIN|POLLRDNORM}, {fd=35, events=POLLIN|POLLRDNORM}, {fd=36, events=POLLIN|POLLRDNORM}, {fd=37, events=POLLIN|POLLRDNORM}, {fd=38, events=POLLIN|POLLRDNORM}, {fd=39, events=POLLIN|POLLRDNORM}, {fd=40, events=POLLIN|POLLRDNORM}, {fd=41, events=POLLIN|POLLRDNORM}, {fd=42, events=POLLIN|POLLRDNORM}, {fd=43, events=POLLIN|POLLRDNORM}, {fd=-1}, {fd=45, events=POLLIN|POLLRDNORM}], 25, -1
17623      0.000929 <... write resumed> ) = 87
17623      0.000057 write(8, "[    CSSD]2012-11-22 01:19:03.14"..., 128) = 128
17623      0.002787 write(8, "[    CSSD]2012-11-22 01:19:03.14"..., 133) = 133
17623      0.002980 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39039, NULL
17654      0.016031 <... nanosleep resumed> NULL) = 0
17654      0.000067 times(NULL)         = 432110560
17654      0.000060 gettimeofday({1353575943, 166007}, NULL) = 0
17654      0.000089 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39040) = 1
17623      0.000056 <... futex resumed> ) = 0
17654      0.000086 pread64(12, 
17623      0.000261 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1) = 0
17623      0.000069 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39041, NULL
17654      0.000444 <... pread64 resumed> "SslcLlik\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 270848) = 512
17654      0.000075 times(NULL)         = 432110560
17654      0.000050 times(NULL)         = 432110560
17654      0.000093 nanosleep({1, 0}, 
17655      0.654202 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17655      0.000081 times(NULL)         = 432110614
17655      0.000054 times(NULL)         = 432110614
17655      0.000055 gettimeofday({1353575943, 821622}, NULL) = 0
17655      0.000123 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39042) = 1
17623      0.000062 <... futex resumed> ) = 0
17655      0.000032 times(
17623      0.000026 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17655      0.000027 <... times resumed> NULL) = 432110614
17623      0.000021 <... futex resumed> ) = 0
17655      0.000028 times(
17623      0.000025 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39043, NULL
17655      0.000052 <... times resumed> NULL) = 432110614
17655      0.000029 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000046 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000092 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000046 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000046 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000088 times(NULL)         = 432110614
17655      0.000056 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000046 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000046 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000163 times(NULL)         = 432110614
17655      0.000050 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000046 times(NULL)         = 432110614
17655      0.000047 times(NULL)         = 432110614
17655      0.000049 gettimeofday({1353575943, 823573}, NULL) = 0
17655      0.000075 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39044) = 1
17623      0.000139 <... futex resumed> ) = 0
17655      0.000065 times(
17623      0.000029 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17655      0.000029 <... times resumed> NULL) = 432110614
17623      0.000023 <... futex resumed> ) = 0
17655      0.000029 gettimeofday(
17623      0.000026 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39045, NULL
17655      0.000026 <... gettimeofday resumed> {1353575943, 823963}, NULL) = 0
17655      0.000044 futex(0x8728f80, FUTEX_WAKE_PRIVATE, 1) = 0
17655      0.000049 clock_gettime(CLOCK_REALTIME, {1353575943, 824108726}) = 0
17655      0.000060 futex(0x8729974, FUTEX_WAIT_PRIVATE, 7529, {0, 999854274}
17639      0.059214 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17639      0.000191 times(NULL)         = 432110619
17639      0.000095 times(NULL)         = 432110619
17639      0.000093 gettimeofday({1353575943, 883762}, NULL) = 0
17639      0.000071 times(NULL)         = 432110619
17639      0.000056 futex(0x8728f80, FUTEX_WAKE_PRIVATE, 1) = 0
17639      0.000059 pwrite64(11, "etoV\1\0\0\0\1\3\n\2\0\0\0\0rac1\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 8704) = 512

统计前面的时间,去掉头尾的数据,你可以发现基本上恰恰是1s。

下面再来看一段rac1节点ocssd进程读写votedisk的信息:

17639      0.000071 pwrite64(11, "etoV\1\0\0\0\1\3\n\2\0\0\0\0rac1\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 8704) = 512
17639      0.001117 pread64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
17639      0.001275 futex(0x862de24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x862de20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}
17667      0.000043 <... futex resumed> ) = 0
17639      0.000027 <... futex resumed> ) = 1
17667      0.000041 futex(0x862dd98, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000061 futex(0x862dd98, FUTEX_WAKE_PRIVATE, 1
17667      0.000033 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000033 <... futex resumed> ) = 0
17667      0.000037 times(
17639      0.000058 gettimeofday(
17667      0.000038 <... times resumed> NULL) = 432111072
17639      0.000032 <... gettimeofday resumed> {1353575949, 386097}, NULL) = 0
17667      0.000069 gettimeofday(
17639      0.000033 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39104
17667      0.000039 <... gettimeofday resumed> {1353575949, 386228}, NULL) = 0
17639      0.000046 <... futex resumed> ) = 1
17623      0.000026 <... futex resumed> ) = 0
17667      0.000044 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000033 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17623      0.000032 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17667      0.000031 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000030 <... futex resumed> ) = 0
17623      0.000097 <... futex resumed> ) = 0
17667      0.000050 futex(0x85fffc0, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000027 times(
17623      0.000030 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17667      0.000032 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000028 <... times resumed> NULL) = 432111073
17623      0.000028 <... futex resumed> ) = 0
17667      0.000041 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17639      0.000026 gettimeofday(
17623      0.000030 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39105, NULL
17667      0.000032 <... futex resumed> ) = 0
17639      0.000024 <... gettimeofday resumed> {1353575949, 386900}, NULL) = 0
17623      0.000049 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17667      0.000080 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39106
17639      0.000039 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17623      0.000032 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17667      0.000028 <... futex resumed> ) = 0
17667      0.000039 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1) = 1
17639      0.000055 <... futex resumed> ) = 0
17667      0.000034 times(
17639      0.000030 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17667      0.000034 <... times resumed> NULL) = 432111073
17639      0.000027 <... futex resumed> ) = 1
17623      0.000029 <... futex resumed> ) = 0
17667      0.000042 futex(0x862dd98, FUTEX_WAKE_PRIVATE, 1
17639      0.000026 gettimeofday(
17623      0.000094 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17667      0.000041 <... futex resumed> ) = 0
17639      0.000025 <... gettimeofday resumed> {1353575949, 387530}, NULL) = 0
17623      0.000052 <... futex resumed> ) = 0
17667      0.000042 futex(0x862de24, FUTEX_WAIT_PRIVATE, 25, NULL
17639      0.000032 futex(0x85fffc0, FUTEX_WAIT_PRIVATE, 2, NULL
17623      0.000032 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17639      0.000031 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17623      0.000028 <... futex resumed> ) = 0
17639      0.000040 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17623      0.000031 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39107, NULL
17639      0.000031 <... futex resumed> ) = 0
17623      0.000024 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000077 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39108
17623      0.000039 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000030 <... futex resumed> ) = 0
17639      0.000040 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1) = 1
17623      0.000073 <... futex resumed> ) = 0
17639      0.000035 times(
17623      0.000030 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17639      0.000030 <... times resumed> NULL) = 432111073
17623      0.000026 <... futex resumed> ) = 0
17639      0.000034 gettimeofday(
17623      0.000031 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39109, NULL
17639      0.000028 <... gettimeofday resumed> {1353575949, 388447}, NULL) = 0
17639      0.000044 clock_gettime(CLOCK_REALTIME, {1353575949, 388620527}) = 0
17639      0.000145 futex(0x87299fc, FUTEX_WAIT_PRIVATE, 7493, {0, 499826473}
17655      0.526617 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17655      0.000583 times(NULL)         = 432111116
17655      0.000073 times(NULL)         = 432111116
17655      0.000055 gettimeofday({1353575949, 916105}, NULL) = 0
17655      0.000185 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39110) = 1
17623      0.000057 <... futex resumed> ) = 0
17655      0.000031 times(
17623      0.000122 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17655      0.000037 <... times resumed> NULL) = 432111116
17623      0.000023 <... futex resumed> ) = 0
17655      0.000029 times(
17623      0.000026 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39111, NULL
17655      0.000025 <... times resumed> NULL) = 432111116
17655      0.000097 times(NULL)         = 432111116
17655      0.000056 times(NULL)         = 432111116
17655      0.000048 times(NULL)         = 432111116
17655      0.000046 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000088 times(NULL)         = 432111116
17655      0.000055 times(NULL)         = 432111116
17655      0.000076 times(NULL)         = 432111116
17655      0.000176 times(NULL)         = 432111116
17655      0.000048 times(NULL)         = 432111116
17655      0.000046 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000046 times(NULL)         = 432111116
17655      0.000096 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000046 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000073 times(NULL)         = 432111116
17655      0.000054 times(NULL)         = 432111116
17655      0.000047 times(NULL)         = 432111116
17655      0.000049 gettimeofday({1353575949, 918267}, NULL) = 0
17655      0.000075 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39112) = 1
17623      0.000049 <... futex resumed> ) = 0
17655      0.000029 times(
17623      0.000025 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17655      0.000026 <... times resumed> NULL) = 432111116
17623      0.000020 <... futex resumed> ) = 0
17655      0.000028 gettimeofday(
17623      0.000025 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39113, NULL
17655      0.000024 <... gettimeofday resumed> {1353575949, 918519}, NULL) = 0
17655      0.000125 futex(0x8728f80, FUTEX_WAKE_PRIVATE, 1) = 0
17655      0.000118 clock_gettime(CLOCK_REALTIME, {1353575949, 918813121}) = 0
17655      0.000106 futex(0x8729974, FUTEX_WAIT_PRIVATE, 7539, {0, 999705879}
17665      0.065982 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17665      0.000078 times(NULL)         = 432111122
17665      0.000061 futex(0x862dea8, FUTEX_WAKE_PRIVATE, 1) = 0
17665      0.000082 times(NULL)         = 432111122
17665      0.000063 gettimeofday({1353575949, 985208}, NULL) = 0
17665      0.000113 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39114) = 1
17623      0.000053 <... futex resumed> ) = 0
17665      0.000037 futex(0x87299fc, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x8728f80, 7494
17623      0.000033 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17665      0.000027 <... futex resumed> ) = 1
17639      0.000023 <... futex resumed> ) = 0
17623      0.000022 <... futex resumed> ) = 0
17665      0.000028 times(
17639      0.000020 times(
17623      0.000024 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39115, NULL
17665      0.000062 <... times resumed> NULL) = 432111122
17639      0.000035 <... times resumed> NULL) = 432111122
17665      0.000031 gettimeofday(
17639      0.000019 times(
17665      0.000024 <... gettimeofday resumed> {1353575949, 985691}, NULL) = 0
17639      0.000041 <... times resumed> NULL) = 432111122
17665      0.000036 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39116
17639      0.000027 gettimeofday(
17665      0.000025 <... futex resumed> ) = 1
17639      0.000022 <... gettimeofday resumed> {1353575949, 985837}, NULL) = 0
17623      0.000033 <... futex resumed> ) = 0
17665      0.000029 times(
17639      0.000020 times(
17623      0.000024 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17665      0.000027 <... times resumed> NULL) = 432111122
17639      0.000022 <... times resumed> NULL) = 432111122
17623      0.000021 <... futex resumed> ) = 0
17665      0.000071 gettimeofday(
17639      0.000035 futex(0x8728f80, FUTEX_WAKE_PRIVATE, 1
17623      0.000027 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39117, NULL
17665      0.000027 <... gettimeofday resumed> {1353575949, 986141}, NULL) = 0
17639      0.000029 <... futex resumed> ) = 0
17665      0.000031 clock_gettime(CLOCK_REALTIME, 
17639      0.000027 pwrite64(11, "etoV\1\0\0\0\1\3\n\2\0\0\0\0rac1\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 8704
17665      0.000346 <... clock_gettime resumed> {1353575949, 986283097}) = 0
17665      0.000251 futex(0x862df34, FUTEX_WAIT_PRIVATE, 7513, {0, 989857903}
17639      0.000250 <... pwrite64 resumed> ) = 512
17639      0.000046 pread64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
17639      0.000793 futex(0x862de24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x862de20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}
17667      0.000039 <... futex resumed> ) = 0
17639      0.000023 <... futex resumed> ) = 1
17667      0.000035 futex(0x862dd98, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000056 futex(0x862dd98, FUTEX_WAKE_PRIVATE, 1
17667      0.000032 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000028 <... futex resumed> ) = 0
17667      0.000030 times(
17639      0.000021 gettimeofday(
17667      0.000024 <... times resumed> NULL) = 432111122
17639      0.000025 <... gettimeofday resumed> {1353575949, 988258}, NULL) = 0
17667      0.000055 gettimeofday(
17639      0.000026 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39118
17667      0.000032 <... gettimeofday resumed> {1353575949, 988362}, NULL) = 0
17639      0.000038 <... futex resumed> ) = 1
17623      0.000021 <... futex resumed> ) = 0
17667      0.000037 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000028 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17623      0.000026 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17667      0.000026 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000084 <... futex resumed> ) = 0
17623      0.000030 <... futex resumed> ) = 0
17667      0.000036 futex(0x85fffc0, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000038 times(
17623      0.000025 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17667      0.000027 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000023 <... times resumed> NULL) = 432111122
17623      0.000023 <... futex resumed> ) = 0
17667      0.000035 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17639      0.000022 gettimeofday(
17623      0.000024 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39119, NULL
17667      0.000027 <... futex resumed> ) = 0
17639      0.000020 <... gettimeofday resumed> {1353575949, 988938}, NULL) = 0
17623      0.000041 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17667      0.000038 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39120
17639      0.000055 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17623      0.000032 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17667      0.000024 <... futex resumed> ) = 0
17667      0.000033 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1) = 1
17639      0.000045 <... futex resumed> ) = 0
17667      0.000028 times(
17639      0.000026 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17667      0.000028 <... times resumed> NULL) = 432111122
17639      0.000023 <... futex resumed> ) = 1
17623      0.000023 <... futex resumed> ) = 0
17667      0.000036 futex(0x862dd98, FUTEX_WAKE_PRIVATE, 1
17639      0.000022 gettimeofday(
17623      0.000025 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17667      0.000025 <... futex resumed> ) = 0
17639      0.000020 <... gettimeofday resumed> {1353575949, 989463}, NULL) = 0
17623      0.000042 <... futex resumed> ) = 0
17667      0.000084 futex(0x862de24, FUTEX_WAIT_PRIVATE, 27, NULL
17639      0.000034 futex(0x85fffc0, FUTEX_WAIT_PRIVATE, 2, NULL
17623      0.000027 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17639      0.000027 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17623      0.000023 <... futex resumed> ) = 0
17639      0.000033 futex(0x85fffc0, FUTEX_WAKE_PRIVATE, 1
17623      0.000026 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39121, NULL
17639      0.000026 <... futex resumed> ) = 0
17623      0.000021 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17639      0.000036 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39122
17623      0.000028 futex(0x85fff38, FUTEX_WAIT_PRIVATE, 2, NULL
17639      0.000024 <... futex resumed> ) = 0
17639      0.000033 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1) = 1
17623      0.000047 <... futex resumed> ) = 0
17639      0.000029 times(
17623      0.000025 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17639      0.000095 <... times resumed> NULL) = 432111122
17623      0.000033 <... futex resumed> ) = 0
17639      0.000031 gettimeofday(
17623      0.000025 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39123, NULL
17639      0.000026 <... gettimeofday resumed> {1353575949, 990258}, NULL) = 0
17639      0.000037 clock_gettime(CLOCK_REALTIME, {1353575949, 990348315}) = 0
17639      0.000061 futex(0x87299fc, FUTEX_WAIT_PRIVATE, 7495, {0, 499909685}
17654      0.254472 <... nanosleep resumed> NULL) = 0
17654      0.000072 times(NULL)         = 432111142
17654      0.000056 nanosleep({0, 190000000}, 
17666      0.092780 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17666      0.000076 times(NULL)         = 432111149
17666      0.000062 futex(0x862dfb8, FUTEX_WAKE_PRIVATE, 1) = 0
17666      0.000062 gettimeofday({1353575950, 337988}, NULL) = 0
17666      0.000062 times(NULL)         = 432111149
17666      0.000061 times(NULL)         = 432111149
17666      0.000092 gettimeofday({1353575950, 338202}, NULL) = 0
17666      0.000054 times(NULL)         = 432111149
17666      0.000070 times(NULL)         = 432111149
17666      0.000046 times(NULL)         = 432111149
17666      0.000062 sendto(15, "P", 1, 0, {sa_family=AF_INET, sin_port=htons(11992), sin_addr=inet_addr("127.0.0.1")}, 16) = 1
17658      0.000114 <... poll resumed> ) = 1 ([{fd=15, revents=POLLIN|POLLRDNORM}])
17666      0.000055 times(
17658      0.000022 read(15, 
17666      0.000083 <... times resumed> NULL) = 432111149
17658      0.000024 <... read resumed> "P", 2000) = 1
17666      0.000041 gettimeofday(
17658      0.000020 times(
17666      0.000023 <... gettimeofday resumed> {1353575950, 338773}, NULL) = 0
17658      0.000026 <... times resumed> NULL) = 432111149
17666      0.000031 clock_gettime(CLOCK_REALTIME, 
17658      0.000021 times(
17666      0.000023 <... clock_gettime resumed> {1353575950, 338874207}) = 0
17658      0.000024 <... times resumed> NULL) = 432111149
17666      0.000034 futex(0x872ac74, FUTEX_WAIT_PRIVATE, 14949, {0, 1898793}
17658      0.000033 futex(0x872ac74, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x872ab60, 14950
17666      0.000029 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17658      0.000025 <... futex resumed> ) = 0
17666      0.000034 futex(0x872ab60, FUTEX_WAIT_PRIVATE, 2, NULL
17658      0.000110 futex(0x872ab60, FUTEX_WAKE_PRIVATE, 1
17666      0.000036 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17658      0.000027 <... futex resumed> ) = 0
17666      0.000033 futex(0x872ac70, FUTEX_WAIT_PRIVATE, 2, NULL
17658      0.000027 futex(0x872ac70, FUTEX_WAKE_PRIVATE, 1
17666      0.000025 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17658      0.000022 <... futex resumed> ) = 0
17666      0.000032 futex(0x872ac70, FUTEX_WAKE_PRIVATE, 1
17658      0.000026 futex(0x872ac74, FUTEX_WAIT_PRIVATE, 14951, NULL
17666      0.000026 <... futex resumed> ) = 0
17658      0.000019 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17666      0.000036 futex(0x872ac74, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x872ab60, 14952
17658      0.000027 futex(0x872ab60, FUTEX_WAIT_PRIVATE, 2, NULL
17666      0.000024 <... futex resumed> ) = 0
17666      0.000027 times(NULL)         = 432111150
17666      0.000100 futex(0x872ab60, FUTEX_WAKE_PRIVATE, 1) = 1
17658      0.000056 <... futex resumed> ) = 0
17666      0.000031 write(26, "t\0\0\0\3\0\0\0\n\2\1\4\232\16\0\0\0\0\0\0\1\0\0\0.\336U\1\0\0\0\0"..., 116
17658      0.000069 futex(0x872ab60, FUTEX_WAKE_PRIVATE, 1
17666      0.000026 <... write resumed> ) = 116
17658      0.000034 <... futex resumed> ) = 0
17666      0.000031 times(
17658      0.000021 gettimeofday(
17666      0.000024 <... times resumed> NULL) = 432111150
17658      0.000026 <... gettimeofday resumed> {1353575950, 339961}, NULL) = 0
17666      0.000041 times(
17658      0.000019 times(
17666      0.000024 <... times resumed> NULL) = 432111150
17658      0.000032 <... times resumed> NULL) = 432111150
17666      0.000072 gettimeofday(
17658      0.000022 poll([{fd=15, events=POLLIN|POLLRDNORM}, {fd=16, events=POLLIN|POLLRDNORM}, {fd=26, events=POLLIN|POLLRDNORM}], 3, -1
17666      0.000052 <... gettimeofday resumed> {1353575950, 340199}, NULL) = 0
17666      0.000034 times(NULL)         = 432111150
17666      0.000046 times(NULL)         = 432111150
17666      0.000045 times(NULL)         = 432111150
17666      0.000059 sendto(18, "P", 1, 0, {sa_family=AF_INET, sin_port=htons(40479), sin_addr=inet_addr("127.0.0.1")}, 16) = 1
17660      0.000109 <... poll resumed> ) = 1 ([{fd=18, revents=POLLIN|POLLRDNORM}])
17666      0.000312 times(
17660      0.000023 read(18, 
17666      0.000048 <... times resumed> NULL) = 432111150
17660      0.000023 <... read resumed> "P", 2000) = 1
17666      0.000038 gettimeofday(
17660      0.000020 times(
17666      0.000023 <... gettimeofday resumed> {1353575950, 341010}, NULL) = 0
17660      0.000025 <... times resumed> NULL) = 432111150
17666      0.000030 clock_gettime(CLOCK_REALTIME, 
17660      0.000051 times(
17666      0.000025 <... clock_gettime resumed> {1353575950, 341139289}) = 0
17660      0.000025 <... times resumed> NULL) = 432111150
17666      0.000034 futex(0x87a6e94, FUTEX_WAIT_PRIVATE, 17881, {0, 1870711}
17660      0.000032 futex(0x87a6e94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x87a50c8, 17882
17666      0.000027 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17660      0.000024 <... futex resumed> ) = 0
17666      0.000034 futex(0x87a50c8, FUTEX_WAIT_PRIVATE, 2, NULL
17660      0.000027 futex(0x87a50c8, FUTEX_WAKE_PRIVATE, 1
17666      0.000025 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17660      0.000023 <... futex resumed> ) = 0
17666      0.000033 futex(0x87a6e90, FUTEX_WAIT_PRIVATE, 2, NULL
17660      0.000026 futex(0x87a6e90, FUTEX_WAKE_PRIVATE, 1
17666      0.000025 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17660      0.000021 <... futex resumed> ) = 0
17666      0.000032 futex(0x87a6e90, FUTEX_WAKE_PRIVATE, 1
17660      0.000026 futex(0x87a6e94, FUTEX_WAIT_PRIVATE, 17883, NULL
17666      0.000025 <... futex resumed> ) = 0
17660      0.000074 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
17666      0.000040 futex(0x87a6e94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x87a50c8, 17884
17660      0.000028 futex(0x87a50c8, FUTEX_WAIT_PRIVATE, 2, NULL
17666      0.000024 <... futex resumed> ) = 0
17666      0.000026 times(NULL)         = 432111150
17666      0.000054 futex(0x87a50c8, FUTEX_WAKE_PRIVATE, 1) = 1
17660      0.000050 <... futex resumed> ) = 0
17666      0.000031 write(17, "H\0\0\0\26\0\0\0\n\2\1\1\243\16\0\0\0\0\0\0\2\0\0\0\274\264U\1\0\0\0\0"..., 72
17660      0.000141 futex(0x87a50c8, FUTEX_WAKE_PRIVATE, 1
17666      0.000027 <... write resumed> ) = 72
17660      0.000060 <... futex resumed> ) = 0
17666      0.000036 gettimeofday(
17660      0.000020 gettimeofday(
17666      0.000024 <... gettimeofday resumed> {1353575950, 342213}, NULL) = 0
17660      0.000042 <... gettimeofday resumed> {1353575950, 342233}, NULL) = 0
17666      0.000044 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39124
17660      0.000027 times(
17666      0.000024 <... futex resumed> ) = 1
17660      0.000022 <... times resumed> NULL) = 432111150
17623      0.000023 <... futex resumed> ) = 0
17666      0.000031 times(
17660      0.000021 poll([{fd=18, events=POLLIN|POLLRDNORM}, {fd=19, events=POLLIN|POLLRDNORM}, {fd=20, events=POLLIN|POLLRDNORM}, {fd=21, events=POLLIN|POLLRDNORM}, {fd=17, events=POLLIN|POLLRDNORM}, {fd=24, events=POLLIN|POLLRDNORM}, {fd=25, events=POLLIN|POLLRDNORM}, {fd=-1}, {fd=29, events=POLLIN|POLLRDNORM}, {fd=30, events=POLLIN|POLLRDNORM}, {fd=31, events=POLLIN|POLLRDNORM}, {fd=32, events=POLLIN|POLLRDNORM}, {fd=33, events=POLLIN|POLLRDNORM}, {fd=34, events=POLLIN|POLLRDNORM}, {fd=35, events=POLLIN|POLLRDNORM}, {fd=36, events=POLLIN|POLLRDNORM}, {fd=37, events=POLLIN|POLLRDNORM}, {fd=38, events=POLLIN|POLLRDNORM}, {fd=39, events=POLLIN|POLLRDNORM}, {fd=40, events=POLLIN|POLLRDNORM}, {fd=41, events=POLLIN|POLLRDNORM}, {fd=42, events=POLLIN|POLLRDNORM}, {fd=43, events=POLLIN|POLLRDNORM}, {fd=-1}, {fd=45, events=POLLIN|POLLRDNORM}], 25, -1
17623      0.000258 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1
17666      0.000041 <... times resumed> NULL) = 432111150
17623      0.000024 <... futex resumed> ) = 0
17666      0.000029 gettimeofday(
17623      0.000025 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39125, NULL
17666      0.000023 <... gettimeofday resumed> {1353575950, 342843}, NULL) = 0
17666      0.000032 clock_gettime(CLOCK_REALTIME, {1353575950, 342925091}) = 0
17666      0.000055 futex(0x862e044, FUTEX_WAIT_PRIVATE, 7499, {0, 999917909}
17654      0.094580 <... nanosleep resumed> NULL) = 0
17654      0.000100 times(NULL)         = 432111158
17654      0.000141 nanosleep({0, 30000000}, NULL) = 0
17654      0.033017 times(NULL)         = 432111160
17654      0.000057 nanosleep({0, 10000000}, NULL) = 0
17654      0.012106 times(NULL)         = 432111161
17654      0.000065 gettimeofday({1353575950, 483046}, NULL) = 0
17654      0.000129 futex(0x85fffc4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x85fff38, 39126) = 1
17623      0.000066 <... futex resumed> ) = 0
17654      0.000036 pread64(12, 
17623      0.000486 futex(0x85fff38, FUTEX_WAKE_PRIVATE, 1) = 0
17623      0.000171 futex(0x85fffc4, FUTEX_WAIT_PRIVATE, 39127, NULL
17654      0.000752 <... pread64 resumed> "SslcLlik\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 270848) = 512
17654      0.000089 times(NULL)         = 432111161
17654      0.000053 times(NULL)         = 432111161
17654      0.000049 nanosleep({1, 0}, 
17639      0.135008 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
17639      0.000044 times(NULL)         = 432111172
17639      0.000029 times(NULL)         = 432111172
17639      0.000029 gettimeofday({1353575950, 619981}, NULL) = 0
17639      0.000037 times(NULL)         = 432111172
17639      0.000030 futex(0x8728f80, FUTEX_WAKE_PRIVATE, 1) = 0
17639      0.000031 pwrite64(11, "etoV\1\0\0\0\1\3\n\2\0\0\0\0rac1\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 8704) = 512
17639      0.000916 pread64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512

下面来重点描述前面开头的2行信息:

17639      0.000071 pwrite64(11, "etoV\1\0\0\0\1\3\n\2\0\0\0\0rac1\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 8704) = 512
17639      0.001117 pread64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512
17639      0.001275 futex(0x862de24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x862de20, {FUTEX_OP_SET, 0, FUTEOracleoracleplus.netX_OP_CMP_GT, 1}

如下是关于linux pwrite64函数的描述:
ssize_t pwrite64( int filedes,
                  const void* buff,
                  size_t nbytes,
                  off64_t offset );

同样,pread64函数也一样:

#include             
ssize_t pread64( int filedes,                 
                  void *buff,                 
                  size_t nbytes,                 
                  off64_t offset );
很清晰,从上面的信息可以看出,rac1节点读和写 votedisk的大小都是512 byte,起写的offset 是8704,读的offset是9216.

注意,这个9216的offset信息,其实正是rac2节点写入的信息,换句话讲,也是通过这个来判断整个cluster中哪些node是可以用的,然后回发出通知进行node驱逐。最后当节点reboot重启后,在ocssd能检测到votedisk后,会重写kill block,你会在ocssd.log中看到类似如下的信息;

[    CSSD]2012-11-22 01:23:28.496 [59100048] >TRACE:   clssnmvDiskOpen: Overwrote kill block for voting disk /dev/raw/raw2
最后,通过分析trace,还发现了其中lseek函数,该函数的解释如下:
position = lseek(handle, offset, direction) ;

各参数定义如下:
u handle:这是一个已经打开的文件句柄,表示所要存取的文件。
u offset:这类似与阵列的索引值。
u direction:direction的值有以下3种情况:
n 0 - 表示从文件起始位置开始移动offset数量
n 1 - 表示从目前文件指针位置移动offset数量
n 2 - 表示从文件末端位置移动offset数量

[root@rac1 tmp]# cat trc.log |grep lseek
17623      0.000026 lseek(14, 512, SEEK_SET
17623      0.000039 <... lseek resumed> ) = 512
17623      0.000018 lseek(14, 1024, SEEK_SET
17623      0.000019 <... lseek resumed> ) = 1024
17623      0.000018 lseek(14, 3584, SEEK_SET
17623      0.000060 <... lseek resumed> ) = 3584
17623      0.000021 lseek(14, 4608, SEEK_SET
17623      0.000019 <... lseek resumed> ) = 4608
17623      0.000027 lseek(14, 5120, SEEK_SET) = 5120
17623      0.000074 lseek(14, 5632, SEEK_SET) = 5632
......省略部分信息
17623      0.000062 lseek(14, 512, SEEK_SET) = 512
17623      0.000080 lseek(14, 1024, SEEK_SET) = 1024
17623      0.000055 lseek(14, 3072, SEEK_SET) = 3072
17623      0.000057 lseek(14, 4608, SEEK_SET) = 4608
17623      0.000054 lseek(14, 5120, SEEK_SET) = 5120
17623      0.000053 lseek(14, 5632, SEEK_SET) = 5632
19950      0.000039 lseek(7, 512, SEEK_SET) = 512
19950      0.000051 lseek(7, 1024, SEEK_SET) = 1024
19950      0.000035 lseek(7, 2560, SEEK_SET) = 2560
19950      0.000110 lseek(7, 3072, SEEK_SET) = 3072
19950      0.000035 lseek(7, 3584, SEEK_SET) = 3584
19950      0.000034 lseek(7, 4096, SEEK_SET) = 4096
19950      0.000063 lseek(7, 512, SEEK_SET) = 512
19950      0.000034 lseek(7, 1024, SEEK_SET) = 1024
19950      0.000033 lseek(7, 2560, SEEK_SET) = 2560
19950      0.000036 lseek(7, 3072, SEEK_SET) = 3072
19950      0.005379 lseek(7, 3584, SEEK_SET) = 3584
19950      0.000039 lseek(7, 4096, SEEK_SET) = 4096
17623      0.000181 lseek(14, 512, SEEK_SET) = 512
17623      0.000118 lseek(14, 1024, SEEK_SET) = 1024
17623      0.000089 lseek(14, 2560, SEEK_SET) = 2560
17623      0.000112 lseek(14, 4608, SEEK_SET) = 4608
17623      0.000086 lseek(14, 5120, SEEK_SET) = 5120
17623      0.000119 lseek(14, 5632, SEEK_SET) = 5632
[root@rac1 tmp]#

这里是fd 7,14其实都是跟crs相关的东西, 准确的说是css相关的文件。这里其实也就可以解释一个问题,occsd进程在读写votedisk时,是如何能够一下就定位到具体的offset呢? 不可能是扫描整个votedisk,知道找到信息为止。 比如rac1节点写的为止是offset 8704.难道要从votedisk头部从0开始扫描? 通过上面的信息,我们可以发现,显示不是的。

我们可以看到是通过lseek函数来进行移动offset,进行访问,每次启动单位都是512的整数倍。你可以发现rac1写的8704,rac2写的9126其实都是512的整数倍。 看下面的一段信息你可以发现,在进行pread64/pwrite64到具体的offset位置之前,都会出现lseek函数:

17623      0.000026 lseek(14, 512, SEEK_SET
17665      0.000035 <... gettimeofday resumed> {1353575947, 546126}, NULL) = 0
17623      0.000039 <... lseek resumed> ) = 512
17665      0.000030 futex(0x87299fc, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x8728f80, 7486
17623      0.000025 read(14, 
17665      0.000109 <... futex resumed> ) = 1
17639      0.000025 <... futex resumed> ) = 0
17623      0.000018 <... read resumed> "\331\7\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
17665      0.000090 gettimeofday(
17639      0.000017 times(
17623      0.000018 lseek(14, 1024, SEEK_SET
17665      0.000023 <... gettimeofday resumed> {1353575947, 546516}, NULL) = 0
17639      0.000036 <... times resumed> NULL) = 432110921
17623      0.000019 <... lseek resumed> ) = 1024
17665      0.000025 times(
17639      0.000017 times(
17623      0.000018 read(14, 
17665      0.000024 <... times resumed> NULL) = 432110921
17639      0.000020 <... times resumed> NULL) = 432110921
17623      0.000036 <... read resumed> "\357\3\264\4B\6K\6m\7\331\7\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
17665      0.000060 gettimeofday(
17639      0.000019 gettimeofday(
17623      0.000018 lseek(14, 3584, SEEK_SET
17665      0.000022 <... gettimeofday resumed> {1353575947, 546830}, NULL) = 0
17639      0.000034 <... gettimeofday resumed> {1353575947, 546848}, NULL) = 0
17623      0.000060 <... lseek resumed> ) = 3584
17665      0.000034 times(
17639      0.000017 times(
17623      0.000018 read(14, 
17665      0.000024 <... times resumed> NULL) = 432110921
17639      0.000020 <... times resumed> NULL) = 432110921
17623      0.000018 <... read resumed> "\t\0L\6\0\0>\0M\6\0\0\177\0N\6\0\0\303\0O\6\0\0\7\1\t\7\0\0K\1"..., 512) = 512
17665      0.000120 gettimeofday(
17639      0.000028 futex(0x8728f80, FUTEX_WAKE_PRIVATE, 1
17623      0.000021 lseek(14, 4608, SEEK_SET
17665      0.000023 <... gettimeofday resumed> {1353575947, 547239}, NULL) = 0
17639      0.000024 <... futex resumed> ) = 0
17623      0.000019 <... lseek resumed> ) = 4608
17665      0.000025 clock_gettime(CLOCK_REALTIME, 
17639      0.000022 pwrite64(11, "etoV\1\0\0\0\1\3\n\2\0\0\0\0rac1\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 8704
17623      0.000263 read(14, 
17665      0.000036 <... clock_gettime resumed> {1353575947, 547374924}) = 0
17623      0.000026 <... read resumed> "\377\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
17665      0.000062 futex(0x862df34, FUTEX_WAIT_PRIVATE, 7509, {0, 999864076}
17623      0.000027 lseek(14, 5120, SEEK_SET) = 5120
17623      0.000044 read(14, "\377\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
17623      0.000074 lseek(14, 5632, SEEK_SET) = 5632
17623      0.000084 read(14, "\0\0\0\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
17639      0.000195 <... pwrite64 resumed> ) = 512
17623      0.000029 write(13, "2012-11-22 01:19:07.545\n[cssd(17"..., 111
17639      0.000284 pread64(11, "etoV\2\0\0\0\1\3\n\2\0\0\0\0rac2\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 9216) = 512

最后可以来个简单性的总结:

1. 正常情况下,ocssd进程仅仅是读取votedisk,读取的大小是512byte,被称为kill block。
2. 在出现脑裂的情况下,每个节点的occsd进程都会将自己节点的信息写入到votedisk中,即写入到kill block中。
3. ocssd进程在读写kill block时,之所以能准确的定位到offset,其实是通过lseek函数来实现的,crs node的信息应该还存在在如下两个文件中,lseek函数就是通过扫描这2个文件来定位到具体的offset位置:
/home/oracle/app/oracle/product/10.2.0/crs/css/mesg/clssus.msb
/home/oracle/app/oracle/product/10.2.0/crs/has/mesg/clsdus.msb

4. 另外,通过跟踪发现,不仅仅是出现脑裂的情况,正常的crsctl stop crs的情况下,occsd进程也会将node信息写入到votedisk中。

--------------------------------------ORACLE-DBA----------------------------------------

最权威、专业的Oracle案例资源汇总之【学习笔记】Oracle 10g rac如何通过votedisk来判断disk心跳

本文由大师惜分飞原创分享,网址:http://www.oracleplus.net/arch/1407.html

Oracle研究中心

关键词:

Oracle RAC磁盘心跳

Oracle RAC votedisk判断节点间心跳