db2loggw 日志写的问题

zcl32

下面是db2在linux平台上的strace的部分片段：
16388 semop(3375126, 0x2b52337f2698, 1) = 0 <0.000028>
16693 <... semtimedop resumed> )        = 0 <0.000350>
16388 semop(1474581, 0x2b52337f2760, 1 <unfinished ...>
16693 pwrite(29, "\327\t\27\0\20\0\0\0_\365\213\3\0\0\0\0\0\330\30}\0008\0\0\0\3
24\31\0\0\f\0\1"..., 4096, 2457600) = 4096 <0.000887>
16693 semop(1474581, 0x2b5232bfcb40, 1) = 0 <0.000043>
16388 <... semop resumed> )             = 0 <0.000979>
16693 semtimedop(3375126, 0x2b5232bfdbf0, 1, {0, 50000000} <unfinished ...>
16388 clock_gettime(0xfffffffe /* CLOCK_??? */, {29, 751142140}) = 0 <0.000006>
16388 semop(3375126, 0x2b52337f2698, 1) = 0 <0.000015>
16693 <... semtimedop resumed> )        = 0 <0.000118>
16388 semop(1474581, 0x2b52337f2760, 1 <unfinished ...>
16693 pwrite(29, "/\n\27\0\20\0\0\0\267\365\213\3\0\0\0\0\0\330\30}\0008\0\0\0\3
24\31\0\0\f\0\1"..., 4096, 2461696) = 4096 <0.006829>
16693 semop(1474581, 0x2b5232bfcb40, 1) = 0 <0.000013>
16693 semtimedop(3375126, 0x2b5232bfdbf0, 1, {0, 50000000} <unfinished ...>
16388 <... semop resumed> )             = 0 <0.006975>
16388 clock_gettime(0xfffffffe /* CLOCK_??? */, {29, 751214321}) = 0 <0.000006>
16388 semop(3375126, 0x2b52337f2698, 1) = 0 <0.000014>
16693 <... semtimedop resumed> )        = 0 <0.000134>
16388 semop(1474581, 0x2b52337f2760, 1 <unfinished ...>
16693 pwrite(29, "\207\n\27\0\20\0\0\0\17\366\213\3\0\0\0\0\0\330\30}\0008\0\0\0
\324\31\0\0\f\0\1"..., 4096, 2457600) = 4096 <0.000890>

下面是oracle在linux平台上的strace片段（我设置了filesystemio_options='none'，所以这里oracle也使用了同步pwrite调用；同时我加大了数据插入的行长，每行5000多字节，这样每次commit时候写的页面大小也从512字节增加到5010左右字节，和db2的4096类似）：
22283 pwrite(260, "\1\"\0\0`L\0\0\30\0\0\0\20\200^\312t\0\0\0\5\0\0\0\30 \34\0\1
\0\0\0"..., 5120, 10010624) = 5120 <0.007376>
22283 semctl(79200295, 39, SETVAL, 0x7070612f00000001) = 0 <0.000015>
22283 times({tms_utime=56, tms_stime=623, tms_cutime=0, tms_cstime=0}) = 4372719
04 <0.000004>
22283 semtimedop(79200295, 0x7fffb5fbd4f0, 1, {1, 390000000}) = 0 <0.000650>
22283 times({tms_utime=56, tms_stime=623, tms_cutime=0, tms_cstime=0}) = 4372719
04 <0.000004>
22283 times({tms_utime=56, tms_stime=623, tms_cutime=0, tms_cstime=0}) = 4372719
04 <0.000004>
22283 pwrite(260, "\1\"\0\0jL\0\0\30\0\0\0\20\200\316Wt\0\0\0\5\0\0\0\32 \34\0\1
\0\0\0"..., 5120, 10015744) = 5120 <0.000912>
22283 semctl(79200295, 39, SETVAL, 0x7070612f00000001) = 0 <0.000014>
22283 times({tms_utime=56, tms_stime=623, tms_cutime=0, tms_cstime=0}) = 4372719
04 <0.000003>
22283 semtimedop(79200295, 0x7fffb5fbd4f0, 1, {1, 390000000}) = 0 <0.000696>
22283 times({tms_utime=56, tms_stime=623, tms_cutime=0, tms_cstime=0}) = 4372719
05 <0.000004>
22283 times({tms_utime=56, tms_stime=623, tms_cutime=0, tms_cstime=0}) = 4372719
05 <0.000003>
22283 pwrite(260, "\1\"\0\0tL\0\0\30\0\0\0\20\200\315\30t\0\0\0\5\0\0\0\34 \34\0
\1\0\0\0"..., 6656, 10020864) = 6656 <0.005955>
22283 semctl(79200295, 39, SETVAL, 0x7070612f00000001) = 0 <0.000052>

两个对比可以看出来，并不是oracle的pwrite就是快。似乎db2中的semtimedop消耗了很多的时间。

这是db2运行时候的vmstat 1结果：
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
1  1  27256  66644  59072 2740280    0    0     0  1012 1212 4291  0  4 71 24  0
0  1  27256  66644  59072 2740284    0    0     0   972 1214 4450  0  4 75 21  0
0  1  27256  67000  59080 2740284    0    0     0  1108 1226 4750  1  4 71 23  0
0  1  27256  67000  59080 2740284    0    0     0   964 1211 4787  1  4 75 20  0
0  1  27256  67000  59080 2740284    0    0     0   972 1214 4825  1  3 75 21  0
0  1  27256  67000  59084 2740280    0    0     0  1032 1216 4808  1  4 67 28  0
1  1  27256  67000  59084 2740280    0    0     0   980 1223 4843  1  3 75 22  0
0  1  27256  67032  59092 2740276    0    0     0  1084 1209 4852  1  4 72 23  0
1  1  27256  67032  59092 2740280    0    0     0   988 1217 4871  1  4 74 20  0
0  1  27256  67024  59092 2740284    0    0     0   972 1215 4434  1  4 75 20  0
0  1  27256  67032  59092 2740284    0    0     0   984 1220 4469  1  3 75 21  0
0  1  27256  67040  59092 2740284    0    0     0  1032 1222 4511  1  3 74 21  0
0  1  27256  66768  59100 2740276    0    0     0  1020 1218 4494  2  3 75 21  0
0  1  27256  66768  59108 2740268    0    0     0   992 1216 4465  1  3 75 22  0
1  1  27256  66768  59108 2740284    0    0     0  1004 1220 4538  1  3 75 21  0
0  1  27256  66768  59108 2740284    0    0     0   976 1213 4895  1  4 74 20  0
1  1  27256  66768  59108 2740284    0    0     0   964 1217 4860  1  4 75 20  0
1  1  27256  60924  59116 2740276    0    0     0  1172 1220 4838  1  4 74 21  0
1  1  27256  60932  59116 2740284    0    0     0   988 1222 4804  1  3 75 21  0
1  1  27256  69944  59120 2740280    0    0     0  1072 1216 4900  0  4 72 23  0
0  1  27256  69944  59120 2740284    0    0     0  1188 1241 4980  1  4 74 20  0

这是ora的：
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
1  1  27256  33252  59256 2740164    0    0     0  3772 1406 7469  5  6 75 14  0
1  0  27256  33004  59256 2740484    0    0     0  2060 1224 5456  3  5 75 18  0
0  1  27256  32756  59276 2740744    0    0     0  4072 1228 5265  2  5 74 19  0
0  1  27256  32508  59276 2740776    0    0     0  2004 1217 5380  3  5 75 18  0
0  1  27256  32136  59276 2741216    0    0     0  3904 1422 6870  4  7 74 15  0
2  0  27256  28160  59276 2741488    0    0     0  1968 1208 7400  5  5 72 18  0
0  1  27256  31664  59276 2741720    0    0     0  2000 1218 5510  2  5 74 19  0
0  1  27256  30656  59288 2741928    0    0     0  3060 1167 5206  2  3 71 23  0
这是ora在异步log模式下(filesystemio_options='setall'):
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
1  0  27256  94340  59912 2744124    0    0   240   706 1839 11856  7  7 79  7  0
1  0  27256  94216  59912 2744296    0    0    64   751 1915 12805 11  9 77  3  0
1  2  27256  93704  59920 2744680    0    0     0  4468 1829 11954 10  7 50 33  0
1  0  27256  93216  59928 2744740    0    0     0   822 1870 12386  9  6 76  9  0
0  1  27256  92968  59932 2745016    0    0     0   766 1946 13043 11 10 76  4  0
0  0  27256 128052  59932 2745032    0    0     0   610 1784 11506 10 11 78  1  0

zcl32

问个最直接的问题吧：
有没有什么办法修改db2 log block IO大小？
缺省4096字节，希望可以修改成为512字节。4096虽然在4k大小扇区上有优势，可以512字节大小扇区呢？
oracle总是512字节，现在在4k扇区上也支持4096大小的块了。sqlserver干脆直接动态支持512-60k区间的日志大小。
有没有什么办法修改db2loggw采用异步写？
理论上单连接的时候同步和异步没有差别，但是在oracle上确实证明了异步IO比同步IO性能要高很多。的确，有些平台异步IO支持不好，但是像windows平台异步IO已经很好了，oracle在windows上就是总用异步，没法修改为同步。linux和aix上的异步也很好了。

wangzhonnew

semtimedop应该就是sqloWaitEDUWaitPost使用的调用，就是你说的线程之间的等待关系：
用户连接的服务器进程发出commit后，都是把commit写到日志缓存中，然后通知日志写线程写入到磁盘上；日志写线程发出异步写后，不是直接通知用户连接的线程的，同样需要等待操作系统异步写完成的通知，然后日志写线程再通知用户连接的线程日志写入完成，用户连接的线程收到该信号后，认为提交完成可以继续处理。

好像从这个片段里面不能看出semtimedop的耗时长啊
16388 semop(3375126, 0x2b52337f2698, 1) = 0 <0.000028>
16693 <... semtimedop resumed> )        = 0 <0.000350>
16388 semop(1474581, 0x2b52337f2760, 1 <unfinished ...>
16693 pwrite(29, "\327\t\27\0\20\0\0\0_\365\213\3\0\0\0\0\0\330\30}\0008\0\0\0\3
24\31\0\0\f\0\1"..., 4096, 2457600) = 4096 <0.000887>
16693 semop(1474581, 0x2b5232bfcb40, 1) = 0 <0.000043>
16388 <... semop resumed> )             = 0 <0.000979>
16693 semtimedop(3375126, 0x2b5232bfdbf0, 1, {0, 50000000} <unfinished ...>
16388 clock_gettime(0xfffffffe /* CLOCK_??? */, {29, 751142140}) = 0 <0.000006>
16388 semop(3375126, 0x2b52337f2698, 1) = 0 <0.000015>
16693 <... semtimedop resumed> )        = 0 <0.000118>
16388 semop(1474581, 0x2b52337f2760, 1 <unfinished ...>
16693 pwrite(29, "/\n\27\0\20\0\0\0\267\365\213\3\0\0\0\0\0\330\30}\0008\0\0\0\3
24\31\0\0\f\0\1"..., 4096, 2461696) = 4096 <0.006829>
16693 semop(1474581, 0x2b5232bfcb40, 1) = 0 <0.000013>
16693 semtimedop(3375126, 0x2b5232bfdbf0, 1, {0, 50000000} <unfinished ...>
16388 <... semop resumed> )             = 0 <0.006975>
16388 clock_gettime(0xfffffffe /* CLOCK_??? */, {29, 751214321}) = 0 <0.000006>
16388 semop(3375126, 0x2b52337f2698, 1) = 0 <0.000014>
16693 <... semtimedop resumed> )        = 0 <0.000134>
16388 semop(1474581, 0x2b52337f2760, 1 <unfinished ...>
16693 pwrite(29, "\207\n\27\0\20\0\0\0\17\366\213\3\0\0\0\0\0\330\30}\0008\0\0\0
\324\31\0\0\f\0\1"..., 4096, 2457600) = 4096 <0.000890>

wangzhonnew

“有没有什么办法修改db2 log block IO大小？”没
“db2loggw采用异步写"好像也只有你先前测试的那个db2set了
开个pmr问问好了

wangzhonnew

77.07   53.733536        7232      7430      1272 semtimedop
应该是多线程造成的semtimedop显得很高吧，因为很多其他的线程也需要调用sqloWaitEDUWaitPost的
ora应该是多进程的，单纯看日志的写进程应该没有那么高的semtimedop吧

那个-c的统计能不能针对线程做？

zcl32

-c似乎不能。关键是好像strace只能针对进程，不能针对线程。
db2_log_nonbuffer_io好像不管用，没啥区别呀。
以前就记得有家公司做性能评测，说db2的数据插入很慢，我当时还以为是bufferpool， logbuffer等的配置有问题呢。这次倒是真的有机会仔细研究下了。
db2在单纯的内存读方面性能还是不错的，就是这个小事务的log，好像不太给力，再研究下吧。

wangzhonnew

恩，大规模的加载数据大家都用load，俺个人很少看到类似单线程小交易的应用，可能因为db2的应用领域和ora不大一样吧

zcl32

非常非常感谢wangchonnew的热心帮助和支持，以后有机会多向你请教。

mdkii

春节期间还有人在研究技术啊，赞一个先。。。
我有几个问题想问问：
1、LZ是从什么地方发现是db2loggw线程不给力的呢。可否测试一下db2 和 ora在不写日志(不知道ora有没有这样的选项）的情况下性能分别是多少？
2、不知道pl sql的语句是不是每句insert都要编译，有没有是这个可能导致的性能问题。
3、mincommit按理说在一个application的情况下应该是不起作用的，因为infocenter上有这么句话：
This grouping of commits will only occur when the value of this parameter is greater than one and when the number of applications connected to the database is greater than or equal to the value of this parameter.
从lz的测试来看为何会越大越慢呢？
4、log io block size应该不会是影响因素吧，为何 512B的就会提高性能？
5、纯属个人意见：db2不采用异步可能是因为虽然异步写效率高，但同步写是不是更为可靠，因为系统调用应该比信号机制更可靠一些。

mdkii

sorry, wangzhonnew 已经问了同样的问题，
看来确实是日志写造成的。
请忽略问题1和问题2。。。。
另外问一下，你用的是本地硬盘还是外部存储？