search

OxDeadmeat / blktrace_merge

Merge blktrace events into a unified/singular io context
GNU General Public License v3.0
0 stars 0 forks source link

[Bug] Flushing of prior io context at 1 second (relative) boundaries is not working correctly in some cases #1

Open OxDeadmeat opened 1 week ago

OxDeadmeat commented 1 week ago

Version : %I-version='06.42-0626-23022024' TestData: test.1

In most cases the output is as expected, io started and completed in one relative second interval is output in that interval. But there are cases where it fails. In the following, relative second 00:24 has no io present -- the next event after 23.* events is at second 25.*. Here we see the trailing io from 23.* being incorrectly displayed in the 25.* time interval.

In the example below, we see four io started and completed within the 23.* second interval are incorrectly output in the 25.* interval.

Find and fix this bug so all 23.* events are output in the 23.* interval and count towards its summary information. This is shown in the test.1 data.

#PS|Prg :Flt   Queue(s)     Q2I(ms)   Q2D(ms)       D2C(ms)            Q2C(ms)     CPU      PID Typ  Size         Sector         Seek  Description            reQ Merges:sectors,...
#--|----:--- ------------- -------- ------------- -------------+---- ------------- --- -------- ---- ---- -------------- ------------- ---------------------- --- ---:-----------------
  0|   1:  1  23.110926555   -.----      0.014647      1.138805 % 98      1.153452   5     1867 WS     56      759744832      -3931896 [dmcrypt_write/2]        0   0
  0|   1:  1  23.112461549   -.----      0.007549      0.062476 % 89      0.070025   5     1867 WS      8      760126776        381888 [dmcrypt_write/2]        0   0
  0|   4:  4  23.112561991   -.----      0.001217      0.057725 % 97      0.058942   5     1867 WS      8      592295448    -167831336 [dmcrypt_write/2]        0   0
  0|   3:  3  23.112562613   -.----      0.000508      0.060264 % 99      0.060772   5     1867 WS      8      592295472            16 [dmcrypt_write/2]        0   0
#SEC: dTime(sec)         Q2I(ms)      Q2D(ms)      D2C(ms)      Q2C(ms;await) io_cnt avrq          KiB  reQ:       seeks prog flt
#SEC@00:23|      4      0      4      0|      40       0      40       0|   20.00   1.1   4 |     0.34  98% |     0.00   0% |     0.34  98% |     0.00   0% |   2.46 |   0.25

#SEC: no io present to summarize, cnt_reads=0 cnt_writes=0 cnt_discards=0

#PS|Prg :Flt   Queue(s)     Q2I(ms)   Q2D(ms)       D2C(ms)            Q2C(ms)     CPU      PID Typ  Size         Sector         Seek  Description            reQ Merges:sectors,...
#--|----:--- ------------- -------- ------------- -------------+---- ------------- --- -------- ---- ---- -------------- ------------- ---------------------- --- ---:-----------------
  0|   2:  2  23.112543800   -.----      0.017706      0.063264 % 78      0.080970   5     1867 WS    160      592295288          -192 [dmcrypt_write/2]        0  20:  8,  8,  8,  8,  8,
  0|   1:  1  23.112557488   -.----      0.002673      0.074198 % 96      0.076871   5     1867 WS     16      592295456             8 [dmcrypt_write/2]        0   2:  8,  8.
  0|   1:  1  23.112682224   -.----      0.011404      0.656701 % 98      0.668105  11     1889 FWFS    0      575481400     -16814072 [jbd2/dm-4-8]            0   0: [BARRIER]
  0|   1:  1  23.113487993   -.----      0.003543      0.473532 % 99      0.477075   5     1867 WFS     8      592295480      16814080 [dmcrypt_write/2]        0   0
  0|   1:  1  25.012611559   -.----      0.009974      1.118728 % 99      1.128702   3     1867 W      16      759744888     167449400 [dmcrypt_write/2]        0   2:  8,  8.
  0|   1:  1  25.012611559   -.----      0.009974      1.118728 % 99      1.128702   3     1867 W      16      759744888     167449400 [dmcrypt_write/2]        0   2:  8,  8.
  0|   1:  1  25.013970946   -.----      0.010619      0.029336 % 73      0.039955   3     1867 WS    136      592295488    -167449416 [dmcrypt_write/2]        0  17:  8,  8,  8,  8,  8,
  0|   1:  1  25.014031365   -.----      0.011103      0.526104 % 97      0.537207  11     1889 FWFS    0      575481544     -16814080 [jbd2/dm-4-8]            0   0: [BARRIER]
  0|   1:  1  25.014670520   -.----      0.003334      0.463077 % 99      0.466411   4     1867 WFS     8      592295624      16814080 [dmcrypt_write/2]        0   0
  0|   1:  1  25.015331918   -.----      0.002641      0.054229 % 95      0.056870   4     1867 WS      8      759744896     167449264 [dmcrypt_write/2]        0   0
  0|   1:  1  25.015484242   -.----      0.003783      0.070968 % 94      0.074751   4     1867 WS     16      592295632    -167449272 [dmcrypt_write/2]        0   2:  8,  8.
  0|   1:  1  25.015567493   -.----      0.007243      0.398202 % 98      0.405445  11     1889 FWFS    0      575481568     -16814080 [jbd2/dm-4-8]            0   0: [BARRIER]
  0|   1:  1  25.016070000   -.----      0.003426      0.412310 % 99      0.415736   4     1867 WFS     8      592295648      16814080 [dmcrypt_write/2]        0   0
  0|   3:  3  25.016699785   -.----      0.005680      0.063582 % 91      0.069262   4     1867 WS      8      681672496      89376840 [dmcrypt_write/2]        0   0
  0|   2:  2  25.016702814   -.----      0.002529      0.067644 % 96      0.070173   4     1867 WS      8      683226384       1553880 [dmcrypt_write/2]        0   0
  0|   1:  1  25.016703760   -.----      0.001240      0.069033 % 98      0.070273   4     1867 WS      8      683255840         29448 [dmcrypt_write/2]        0   0
  0|   1:  1  25.016888688   -.----      0.003820      0.010305 % 72      0.014125   4     1867 WS     16      592295656     -90960192 [dmcrypt_write/2]        0   2:  8,  8.
  0|   1:  1  25.016911200   -.----      0.006948      0.648391 % 98      0.655339  11     1889 FWFS    0      575481592     -16814080 [jbd2/dm-4-8]            0   0: [BARRIER]
  0|   1:  1  25.017675457   -.----      0.010543      0.375871 % 97      0.386414   4     1867 WFS     8      592295672      16814080 [dmcrypt_write/2]        0   0
#SEC@00:25|     18      0     18      0|     212       0     212       0|   23.56   0.0   3 |     0.32  98% |     0.00   0% |     0.32  98% |     0.00   0% | 986.19 |  98.62 |    0    0    3