| |
|
RSS Feed - WebSphere MQ Support
|
RSS Feed - Message Broker Support
|
| TripleWrite |
« View previous topic :: View next topic » |
| Author |
Message
|
| tczielke |
 Posted: Wed Oct 29, 2014 12:09 pm Post subject: |
 |
|
Guardian
Joined: 08 Jul 2010
Posts: 939
Location: Illinois, USA
|
I just noticed this mqlogperf.sh tool that was recently highlighted on the RSS feed -> http://www-01.ibm.com/support/docview.wss?uid=swg21678834&myns=swgws&mynp=OCSSFKSJ&mync=R
Pretty cool. I mention it on this thread, because I believe you could also use this mqlogperf.sh tool to get a feel for how many partial page writes your queue manager logger is doing. For example, I traced a Test Linux queue manager's logger thread for 15 minutes and then used the mqlogperf.sh to analyze the data. I checked how many writes were not a multiple of 4096, and I only saw 2 out of the 1237 writes. So 99% of the logger writes would have made no performance difference if we were SingleWrite or TripleWrite (if I understand this concept correctly). |
|
| Back to top |
|
 |
| bruce2359 |
| Posted: Wed Oct 29, 2014 1:35 pm Post subject: |
|
|
Poobah
Joined: 05 Jan 2008
Posts: 9396
Location: US: west coast, almost. Otherwise, enroute.
|
Is there a disk-hardware doctor in the crowd?!
_________________
I like deadlines. I like to wave as they pass by.
ב''ה
Lex Orandi, Lex Credendi, Lex Vivendi. As we Worship, So we Believe, So we Live. |
|
| Back to top |
|
|
| PeterPotkay |
| Posted: Wed Oct 29, 2014 2:39 pm Post subject: |
|
|
Poobah
Joined: 15 May 2001
Posts: 7717
|
tczielke, what kind of load did you drive against that QM in your test where you say only 2 partial page writes?
_________________
Peter Potkay
Keep Calm and MQ On |
|
| Back to top |
|
|
| tczielke |
| Posted: Wed Oct 29, 2014 5:15 pm Post subject: |
|
|
Guardian
Joined: 08 Jul 2010
Posts: 939
Location: Illinois, USA
|
I just used the normal load that the queue manager runs under.
I also did this exercise again, but this time with an strace on the amqzmuc0 logger process. This showed that those 2160 byte writes were actually to the amqhlctl.lfh file. So actually, all the writes to a log file were multiples of 4096, it looks like. |
|
| Back to top |
|
|
| Andyh |
| Posted: Thu Oct 30, 2014 1:14 am Post subject: |
|
|
Master
Joined: 29 Jul 2010
Posts: 237
|
I wasn't involve with the production of this script and have never looked at it, however ANY performance analysis performed with some level of MQ trace active has to be treated with a very large pinch of salt.
MQ will always write to the recovery log extents in units of 4096 bytes, regardless of the log write integrity selected. The single/triple write behaviour is related to the re-writing of a new version of a 4096 byte page at the same location. |
|
| Back to top |
|
|
| tczielke |
| Posted: Thu Oct 30, 2014 5:20 am Post subject: |
|
|
Guardian
Joined: 08 Jul 2010
Posts: 939
Location: Illinois, USA
|
Thanks for the info. I reviewed the strace output with the mqlogperf.sh output.
mqlogperf.sh had 2,547 writes.
strace had 2,547 lseeks and 2,547 writes (write and writev system calls combined).
I would assume this means that there was no need to do more than a single write for any write to the log, but just an educated guess on my part. |
|
| Back to top |
|
|
| tczielke |
| Posted: Thu Oct 30, 2014 8:35 am Post subject: |
|
|
Guardian
Joined: 08 Jul 2010
Posts: 939
Location: Illinois, USA
|
I was curious, so I tested the following out on one of my Sandbox Linux x86 7.5.0.4 queue managers.
First Test:
1. LogWriteIntegrity=TripleWrite with circular logging
2. Activate Trace on logger thread
3. Run following amqsblst for 2000 messages and then stop trace:
./amqsblst -W 15 -u 10 -s 100 -t 2 -c 1000000 QM1 TCZ.TEST1
4. mqlogperf.sh recorded 409 log writes with the pattern of a 4096 write following by a larger write (i.e. 24576).
Second Test:
1. LogWriteIntegrity=SingleWrite with circular logging
2. Activate Trace on logger thread
3. Run following amqsblst for 2000 messages and then stop trace:
./amqsblst -W 15 -u 10 -s 100 -t 2 -c 1000000 QM1 TCZ.TEST1
4. mqlogperf.sh recorded 204 log writes with now just a larger write (i.e. 24576).
You can see for the same test that with TripleWrite, the log writes doubled.
This TripleWrite pattern of smaller 4096 writes followed by a larger write matched what I was seeing with my Test queue manager. Based on this evidence, I would say my Test queue manager was doing significantly more log writes due to being at TripleWrite.
Also, I am not sure about this blurb from the mqlogperf.sh technote:
| Quote: |
| IBM MQ queue managers that use circular logging must log to disk the contents of all transacted messages, while queue managers that use linear logging must log all persistent messages sent to the queue manager. |
I was using circular logging for both test cases, but no writes were going to the log during my initial tests when my queue had DEFPSIST(NO). Once I set my queue to DEFPSIST(YES), I started getting all the log writes. For both of those cases, the PUTs for amqsblst were under syncpoint. That blurb made me think that for circular logging, any PUT (whether persistent or non-persistent) would get written to the log if it was under syncpoint. Maybe I am misunderstanding what is being said in the blurb. |
|
| Back to top |
|
|
| Andyh |
| Posted: Thu Oct 30, 2014 12:19 pm Post subject: |
|
|
Master
Joined: 29 Jul 2010
Posts: 237
|
Non-persistent messages do not need to be logged, regardless of whether the put/get is in syncpoint.
Transactions involving only non-persistent messages do not result in any log records being written. |
|
| Back to top |
|
|
| tczielke |
| Posted: Thu Oct 30, 2014 12:44 pm Post subject: |
|
|
Guardian
Joined: 08 Jul 2010
Posts: 939
Location: Illinois, USA
|
Thanks for the info, Andy. I thought that was how it worked (just persistent messages go to the log), but I do have to admit the syncpoint part of it can muddy the waters for me.
Also, for anyone else interested, I found this kind of interesting with comparing the mqlogperf.sh output to the strace on my Test queue manager that uses TripleWrite.
Here is a snippet from the mqlogperf.sh:
| Quote: |
## IBM mqlogperf.sh V1.2 Disk throughput
## Timestamp Bytes uSec IO:MiB/s
19:02:28.698 4096 730 5.351
19:02:28.982 4096 788 4.957
19:02:34.916 4096 539 7.247
19:02:34.918 4096 491 7.956
19:02:34.921 16384 875 17.857 |
Here is the corresponding snippet for this activity from the strace:
| Quote: |
[pid 10204] 1414627348.696920 lseek(17, 175124480, SEEK_SET) = 175124480
[pid 10204] 1414627348.697452 write(17, "\345\r\363\6\0\0\0\0\1\2738\264\35\362\342\305\303\344\331\311\343\350`\342\350\325\303La\342\305\331"..., 4096) = 4096
[pid 10204] 1414627348.980998 lseek(17, 175120384, SEEK_SET) = 175120384
[pid 10204] 1414627348.981717 write(17, "\275\16\363\6\0\0\0\0\1\2738\264\36\312\342\305\303\344\331\311\343\350`\342\350\325\303La\342\305\331"..., 4096) = 4096
[pid 10204] 1414627354.915471 lseek(17, 175124480, SEEK_SET) = 175124480
[pid 10204] 1414627354.916013 write(17, "\356\17\363\6\0\0\0\0\1\2738\264\37\373\342\305\303\344\331\311\343\350`\342\350\325\303La\342\305\331"..., 4096) = 4096
[pid 10204] 1414627354.917755 lseek(17, 175120384, SEEK_SET) = 175120384
[pid 10204] 1414627354.918315 write(17, "\356\17\363\6\0\0\0\0\1\2738\264\37\373\342\305\303\344\331\311\343\350`\342\350\325\303La\342\305\331"..., 4096) = 4096
[pid 10204] 1414627354.920579 lseek(17, 175124480, SEEK_SET) = 175124480
[pid 10204] 1414627354.921022 writev(17, [{"\356\17\0\0\0\0\0\0\1\2738\264/\373\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 12288}, {"\"\3X\2\0\0\0\0\1\2738\264C/ "..., 4096}], 2) = 16384 |
pid 10204 is the Linux thread id that the I/O logger is running on. The file descriptor for the log file that the logger thread is writing to is 17. The thread is using an lseek with SEEK_SET to position itself to an offset of the log file, and then do a write. What is interesting is you can see the same offset is used for some of the 4096 writes (i.e. 175124480), and then the larger write of 16384 bytes uses one of those same offsets (i.e. 175124480). So it does look like it writes over the same location of the file several times. I see this behavior with TripleWrite. For SingleWrite, I only see the larger write happening once. Interesting. |
|
| Back to top |
|
|
|
|
|
|
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum
|
|
|
|
