Events out of order
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512
I captured a trace with blktrace -d /dev/sde -o - > trace, then later parsed it with blkparse -i - < trace, and the events are out of order.
It appears that they come in blocks from one cpu, then the other cpu,
and the timestamps roll backwards when switching to the other cpu. Why aren't they in the proper order?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
iQEcBAEBCgAGBQJUo1XSAAoJENRVrw2cjl5RjS8H/2fiGBHhJ9PRwjAMEBAIqtgj Oaz3BDI/ilA9+feGs39/YWrKJbgPr3p+1Sat6I7rxwt6sSPm8+O/NkwEQDZQAund R5Urinh0Yov5I0mxUawhJs24YzrWiA8IfEdb7Nu772ihfKge6j32h734RvG9HSDh SaSAOFAoAdDQx2aMR/AFdq9VlO2/dwpUgW2CxyehO341lHwpE6qjAITQ6aLtOJr9 lMAwTxifBdzsnGjafe/bawTqmwCj0ZA+SVTsDHJYFDcO1EpCo6llt3CG4bgXHXB0 Kk6RBHS+7aXlQybCPg5J2/jvfED0ohX4CFqGxuKU5t1+ZJKcYDCDZtd2rp7C6b4=qZgI -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512
I captured a trace with blktrace -d /dev/sde -d /dev/sdf -o - > trace, then parsed it with blkparse -i - < trace, and I have noticed that the events are out of order. They appear to come in batches from one cpu, then the other, and when transitioning from one batch to the other, the timestamps roll backwards.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
iQEcBAEBCgAGBQJUo1a3AAoJENRVrw2cjl5RPEYH/1q7V0fKvMXRtGWtaHrxkefp Wzjyh8MekQL2gRROq0Fa7pjwUtGAsfuFW9K8RmFtJaNBemM+zWRXkF7vX6CPjVG+ IqO65M628b12A/GLmwPkK1vZ4qM/x2SE9h+JpUH068QUKQw+EyEVEIxrflC6al+S LBY/mST0HOFog3dYOK7Bx6rKbRfyNOiw729xltq8Vpwn5HVHl3R3ZzvFir1ZV1VX 2foZquHEfFJsb9hHE4QZylBCqLE6txFnAW6PitqNtJyy8ow82Q+gyw2xSeTvxGJH 4KDWVbsTLYRihIf1dg+Uk7gEfIejO21H8Cb/O33RD7iHQO+uyuaE1UP9TNgyS6w=hj/D -----END PGP SIGNATURE-----
Quoted 6 lines · Phillip Susi
I captured a trace with blktrace -d
/dev/sde-o - > trace, then later parsed it with blkparse -i - < trace, and the events are out of order.
It appears that they come in blocks from one cpu, then the other cpu,
and the timestamps roll backwards when switching to the other cpu. Why aren't they in the proper order?
Can you please share an example ? How much time backward you observed after switch ?
--
Alireza
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512
Quoted 2 lines · Alireza Haghdoost
Can you please share an example ? How much time backward you observed after switch ?
8,64 2 606 0.019550771 480 D R 2816 + 128 [kworker/2:1H] 8,64 2 607 0.019551057 480 R R 2816 + 128 [0] 8,64 2 608 0.019551151 480 I R 2816 + 128 [kworker/2:1H] 8,64 2 609 0.019979263 0 D R 2816 + 128 [swapper/2] 8,64 2 610 0.019980728 0 D R 2944 + 128 [swapper/2] 8,64 2 611 0.020403185 0 C R 2816 + 128 [0] 8,64 2 612 0.020416690 0 R R 2944 + 128 [0] 8,64 2 613 0.020416798 0 I R 2944 + 128 [swapper/2] 8,64 2 614 0.020420237 480 D R 2944 + 128 [kworker/2:1H] 8,64 2 615 0.020420511 480 R R 2944 + 128 [0] 8,80 2 2 0.000000042 27566 G R 0 + 8 [hdparm] 8,80 2 3 0.000001130 27566 P N [hdparm] 8,80 2 4 0.000003388 27566 Q R 8 + 8 [hdparm] 8,80 2 5 0.000004343 27566 M R 8 + 8 [hdparm] 8,80 2 6 0.000005793 27566 Q R 16 + 8 [hdparm] 8,80 2 7 0.000005979 27566 M R 16 + 8 [hdparm] 8,80 2 8 0.000006934 27566 Q R 24 + 8 [hdparm] 8,80 2 9 0.000007092 27566 M R 24 + 8 [hdparm]
Come to think of it, in this example it didn't even switch to the other cpu, just the other device ( though typically when that happens it seems to also switch the cpu ).
Here is one that is worse:
8,64 1 1026 0.075645831 27565 Q R 7800 + 8 [hdparm] 8,64 1 1027 0.075646030 27565 M R 7800 + 8 [hdparm] 8,64 1 1028 0.075646911 27565 Q R 7808 + 8 [hdparm] 8,64 1 1029 0.075647447 27565 G R 7808 + 8 [hdparm] 8,80 0 1 0.035128312 27566 Q R 5376 + 8 [hdparm] 8,80 0 2 0.035130922 27566 G R 5376 + 8 [hdparm] 8,80 0 3 0.035131724 27566 P N [hdparm]
Would you like the raw trace file?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
iQEcBAEBCgAGBQJUo2wwAAoJENRVrw2cjl5RIooH/juX4p9Cz9XLjYbpLL0HtZhb JnGw4yaZQEBeqBs5h1LL3A6JZnNHx/yAxMO6LteWr4aQf+nKWUyLD+Yj0jid3n+u MF4yAwYI7PtJZtRzYpY0YlCorQdX2GKj1ajcX4mCHXrmMr2AXr4Ionyek042Q/Lp cpJRJUL7OfHHhtpTRTf5Xg36yLo/nK1cIFU0bNz21U3o7jWKRKo7PAmulZymCdN0 4FULblVSqiC3iqWPFQC8ScYLxZa0uKnsA73hFB4NbVXVXOoDor2DbgiQoF8gKVWn MmYlMwf5wfBwuPDTaTcVVLNA7weK6Gs79T71/6FLiJGnpaeedDAQyKvYx3j+5PQ=nd6f -----END PGP SIGNATURE-----
Seems to me like you don't run blktrace and blkparse appropriately. blktrace stores IO trace in multiple files where each file is associated to a CPU core. However, you force the output of blktrace to redirect into a single file. This make some timing Confusion for blkparse in the next step. You are using live blkparse option (-i -) inappropriately. If you want to run live blkparse, you need to feed it through blktrace pipe. Like:
#blktrace -d /dev/sda -o - | blkparse -i -
If you want to store trace in a file then parse it offline, you need to use --input option of blkparse.
Hope it helps
Alireza
Quoted 53 lines · Phillip Susi
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512Quoted 2 lines · Alireza Haghdoost
Can you please share an example ? How much time backward you observed after switch ?
8,64 2 606 0.019550771 480 D R 2816 + 128 [kworker/2:1H] 8,64 2 607 0.019551057 480 R R 2816 + 128 [0] 8,64 2 608 0.019551151 480 I R 2816 + 128 [kworker/2:1H] 8,64 2 609 0.019979263 0 D R 2816 + 128 [swapper/2] 8,64 2 610 0.019980728 0 D R 2944 + 128 [swapper/2] 8,64 2 611 0.020403185 0 C R 2816 + 128 [0] 8,64 2 612 0.020416690 0 R R 2944 + 128 [0] 8,64 2 613 0.020416798 0 I R 2944 + 128 [swapper/2] 8,64 2 614 0.020420237 480 D R 2944 + 128 [kworker/2:1H] 8,64 2 615 0.020420511 480 R R 2944 + 128 [0] 8,80 2 2 0.000000042 27566 G R 0 + 8 [hdparm] 8,80 2 3 0.000001130 27566 P N [hdparm] 8,80 2 4 0.000003388 27566 Q R 8 + 8 [hdparm] 8,80 2 5 0.000004343 27566 M R 8 + 8 [hdparm] 8,80 2 6 0.000005793 27566 Q R 16 + 8 [hdparm] 8,80 2 7 0.000005979 27566 M R 16 + 8 [hdparm] 8,80 2 8 0.000006934 27566 Q R 24 + 8 [hdparm] 8,80 2 9 0.000007092 27566 M R 24 + 8 [hdparm]Come to think of it, in this example it didn't even switch to the other cpu, just the other device ( though typically when that happens it seems to also switch the cpu ).
Here is one that is worse:
8,64 1 1026 0.075645831 27565 Q R 7800 + 8 [hdparm] 8,64 1 1027 0.075646030 27565 M R 7800 + 8 [hdparm] 8,64 1 1028 0.075646911 27565 Q R 7808 + 8 [hdparm] 8,64 1 1029 0.075647447 27565 G R 7808 + 8 [hdparm] 8,80 0 1 0.035128312 27566 Q R 5376 + 8 [hdparm] 8,80 0 2 0.035130922 27566 G R 5376 + 8 [hdparm] 8,80 0 3 0.035131724 27566 P N [hdparm]Would you like the raw trace file?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1iQEcBAEBCgAGBQJUo2wwAAoJENRVrw2cjl5RIooH/juX4p9Cz9XLjYbpLL0HtZhb JnGw4yaZQEBeqBs5h1LL3A6JZnNHx/yAxMO6LteWr4aQf+nKWUyLD+Yj0jid3n+u MF4yAwYI7PtJZtRzYpY0YlCorQdX2GKj1ajcX4mCHXrmMr2AXr4Ionyek042Q/Lp cpJRJUL7OfHHhtpTRTf5Xg36yLo/nK1cIFU0bNz21U3o7jWKRKo7PAmulZymCdN0 4FULblVSqiC3iqWPFQC8ScYLxZa0uKnsA73hFB4NbVXVXOoDor2DbgiQoF8gKVWn MmYlMwf5wfBwuPDTaTcVVLNA7weK6Gs79T71/6FLiJGnpaeedDAQyKvYx3j+5PQ> =nd6f -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Quoted 11 lines · Alireza Haghdoost
Seems to me like you don't run blktrace and blkparse appropriately. blktrace stores IO trace in multiple files where each file is associated to a CPU core. However, you force the output of blktrace to redirect into a single file. This make some timing Confusion for blkparse in the next step. You are using live blkparse option (-i -) inappropriately. If you want to run live blkparse, you need to feed it through blktrace pipe. Like:
#blktrace -d/dev/sda-o - | blkparse -i -If you want to store trace in a file then parse it offline, you need to use --input option of blkparse.
Whether it is piped directly, or buffered in a file on disk makes no difference; blkparse sees exactly the same input byte for byte, and produces the same output. The man page recommends this interactive method and doesn't mention that it borks up the ordering, but I suppose I can try it the other way and see if that helps. If the interactive method doesn't work correctly it should either be fixed or the man page should mention this and not recommend its use.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (MingW32)
iQEcBAEBAgAGBQJUpAn0AAoJENRVrw2cjl5Rt98H/R+QLa7VQ2uWIv2yJmUPQDX/ 9+qExZ1lEpJ39dtzDVZJwVISNQvUtEUA42hzPetuO3NQjiamThsh4koEw2cvr46G m809gpMy9LifkxqG8ufE+sp9FAReoRhZ/9wjFWiMcWLP4JnmssRnJCs953PzVYNF i6kYeRXqKJS8kWE1j9lXPtFCDhjhBRVoHCevBa3IxdP5Ri83YpQdLscvoXjSNSwe NOiJloFO0tvbO7Lj5UY1rhB8ZNLxyGqSHeiEMUWiqTZONffEBoDmNiS6om36Qpjp 2kim1Ug838a61AgGkZHR8m4CRoUMLKDprG9mKOGlZKH8pIp9Y5iO0Md17OiY48c=VgcL -----END PGP SIGNATURE-----
Quoted 16 lines · Phillip Susi
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1Quoted 11 lines · Alireza Haghdoost
Seems to me like you don't run blktrace and blkparse appropriately. blktrace stores IO trace in multiple files where each file is associated to a CPU core. However, you force the output of blktrace to redirect into a single file. This make some timing Confusion for blkparse in the next step. You are using live blkparse option (-i -) inappropriately. If you want to run live blkparse, you need to feed it through blktrace pipe. Like:
#blktrace -d/dev/sda-o - | blkparse -i -If you want to store trace in a file then parse it offline, you need to use --input option of blkparse.
Quoted 7 lines
Whether it is piped directly, or buffered in a file on disk makes no difference; blkparse sees exactly the same input byte for byte, and produces the same output. The man page recommends this interactive method and doesn't mention that it borks up the ordering, but I suppose I can try it the other way and see if that helps. If the interactive method doesn't work correctly it should either be fixed or the man page should mention this and not recommend its use.
It's been a while since I looked at this, but looks like blkparse has a pipeline mode and a more exact mode. In pipeline mode, it's really trying to get data to the screen quickly and without using a huge amount of resources. In order to put things in order, it would need to buffer the entire stream before outputting anything. So instead it works in chunks, which is what you're seeing.
It enables pipeline mode when the input file from -i is a pipe. You'll get better results if you allow blktrace to output into a collection of files and pass the prefix to blkparse.
instead of blktrace -o - use blktrace -o prefix ; blkparse -i prefix
For multiple devices, iowatcher uses a directory to store all of them, which is easier.
If you really want a single file result, take the per-cpu files from blktrace, run them through blkparse and add -d dumpfile, which will sort and pack all the results into a single binary file. It's compressable and you can then delete all the per-cpu files.
-chris
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Quoted 6 lines · Chris Mason
It's been a while since I looked at this, but looks like blkparse has a pipeline mode and a more exact mode. In pipeline mode, it's really trying to get data to the screen quickly and without using a huge amount of resources. In order to put things in order, it would need to buffer the entire stream before outputting anything. So instead it works in chunks, which is what you're seeing.
Makes sense; it would be nice if the man page mentioned this drawback.
Quoted 7 lines
It enables pipeline mode when the input file from -i is a pipe. You'll get better results if you allow blktrace to output into a collection of files and pass the prefix to blkparse.
instead of blktrace -o - use blktrace -o prefix ; blkparse -i prefix
Quoted 7 lines
For multiple devices, iowatcher uses a directory to store all of them, which is easier.
If you really want a single file result, take the per-cpu files from blktrace, run them through blkparse and add -d dumpfile, which will sort and pack all the results into a single binary file. It's compressable and you can then delete all the per-cpu files.
Thanks; I thought I read something like that at one point but couldn't find it in the man page last night.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (MingW32)
iQEcBAEBAgAGBQJUpBGiAAoJENRVrw2cjl5R5EcH/AoLTOH7JzM62//2/V4Ely5U OTnDkD4Aq2ydS7SQ3otidPnCJ46zCwlACZxJHknxM3RkLkXQUsqjXJ9J0l6Bitav u06jZHyr07d9ysRexeLMpPJsdzFzrY41G8ZjTNFJJBGgNv/y8zlqT1gXZ8QjJYjw XSsBVy+8D7yPJRAwX7eXbrfwKRfe16N+ujQC1DXnVOVKDKeP1inG7vRDdUuzjciA 63Gf8Kdk8E4Rlh9zyR8QWSB15Tp92/bLIeoJjZIoqsLlrRFoizREyPLpVXhg3Zhn M6C+/H9cm+wB2KDiDESLm7uNyokYeAyQGbesj7/WTj/Lccv29drFMF9cCYLk4nk¿Zz -----END PGP SIGNATURE-----
Quoted 23 lines · Phillip Susi
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1Quoted 6 lines · Chris Mason
It's been a while since I looked at this, but looks like blkparse has a pipeline mode and a more exact mode. In pipeline mode, it's really trying to get data to the screen quickly and without using a huge amount of resources. In order to put things in order, it would need to buffer the entire stream before outputting anything. So instead it works in chunks, which is what you're seeing.
Makes sense; it would be nice if the man page mentioned this drawback.
Quoted 10 lines
It enables pipeline mode when the input file from -i is a pipe. You'll get better results if you allow blktrace to output into a collection of files and pass the prefix to blkparse.
instead of blktrace -o - use blktrace -o prefix ; blkparse -i prefix
For multiple devices, iowatcher uses a directory to store all of them, which is easier.
Quoted 7 lines
Quoted 4 lines
If you really want a single file result, take the per-cpu files from blktrace, run them through blkparse and add -d dumpfile, which will sort and pack all the results into a single binary file. It's compressable and you can then delete all the per-cpu files.
Thanks; I thought I read something like that at one point but couldn't find it in the man page last night.
What Chris writes is completely correct. Pre-process the per-cpu files and use that binary sorted trace file for the inspection (or replay) tools.
BTW, the behavior is documented in the README:
----
If you want to do live tracing, you can pipe the data between blktrace and blkparse:
% blktrace -d <device> -o - | blkparse -i -
This has a small risk of displaying some traces a little out of sync, since it will do batch sorts of input events.
----
But I agree, would not hurt to put this in the man pages too.
Signature · 1 line
Jens Axboe