前不久写了一篇关于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, FUTEX_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中。
发表回复