proactive drops ("streaming mode") varies from run to run
Closed this issue · 1 comments
jtmoon79 commented
Problem
Dropped blocks varies from run to run. The same inputs should produce exactly the same outputs.
To Reproduce
Run compare-current-and-expected/update.sh then compare-current-and-expected/compare.sh.
The differences often look like:
$ ./tools/compare-current-and-expected/update.sh
...
$ ./tools/compare-current-and-expected/compare.sh
...
Difference Preview of stderr:
+ diff --text -y --width=140 --suppress-common-lines ./tools/compare-current-and-expected/current.stderr ./tools/compare-current-and-expected/expected.stderr
lines high : 17 | lines high : 15
streaming: BlockReader::drop_block() : Ok 16, Err 5 | streaming: BlockReader::drop_block() : Ok 18, Err 3
streaming: LineReader::drop_line() : Ok 64, Err 0 | streaming: LineReader::drop_line() : Ok 66, Err 0
streaming: SyslineReader::drop_sysline(): Ok 63, Err 5 | streaming: SyslineReader::drop_sysline(): Ok 65, Err 3
blocks high : 14 | blocks high : 15
lines high : 12 | lines high : 13
streaming: BlockReader::drop_block() : Ok 5, Err 2 | streaming: BlockReader::drop_block() : Ok 4, Err 2
streaming: LineReader::drop_line() : Ok 3, Err 0 | streaming: LineReader::drop_line() : Ok 2, Err 0
streaming: SyslineReader::drop_sysline(): Ok 3, Err 4 | streaming: SyslineReader::drop_sysline(): Ok 2, Err 5
streaming: BlockReader::drop_block() : Ok 0, Err 1 | streaming: BlockReader::drop_block() : Ok 1, Err 2
streaming: LineReader::drop_line() : Ok 2, Err 3 | streaming: LineReader::drop_line() : Ok 4, Err 3
streaming: SyslineReader::drop_sysline(): Ok 5, Err 10 | streaming: SyslineReader::drop_sysline(): Ok 7, Err 8
streaming: BlockReader::drop_block() : Ok 1, Err 2 | streaming: BlockReader::drop_block() : Ok 0, Err 1
streaming: LineReader::drop_line() : Ok 4, Err 3 | streaming: LineReader::drop_line() : Ok 2, Err 3
streaming: SyslineReader::drop_sysline(): Ok 7, Err 8 | streaming: SyslineReader::drop_sysline(): Ok 5, Err 10
streaming: BlockReader::drop_block() : Ok 6, Err 0 | streaming: BlockReader::drop_block() : Ok 5, Err 1
streaming: LineReader::drop_line() : Ok 13, Err 0 | streaming: LineReader::drop_line() : Ok 11, Err 0
streaming: SyslineReader::drop_sysline(): Ok 8, Err 0 | streaming: SyslineReader::drop_sysline(): Ok 7, Err 1
blocks high : 12 | blocks high : 11
lines high : 14 | lines high : 13
streaming: BlockReader::drop_block() : Ok 3, Err 2 | streaming: BlockReader::drop_block() : Ok 4, Err 2
streaming: LineReader::drop_line() : Ok 5, Err 0 | streaming: LineReader::drop_line() : Ok 6, Err 0
streaming: SyslineReader::drop_sysline(): Ok 5, Err 8 | streaming: SyslineReader::drop_sysline(): Ok 6, Err 7
streaming: BlockReader::drop_block() : Ok 97, Err 39 | streaming: BlockReader::drop_block() : Ok 98, Err 38
streaming: LineReader::drop_line() : Ok 425, Err 0 | streaming: LineReader::drop_line() : Ok 426, Err 0
streaming: SyslineReader::drop_sysline(): Ok 175, Err 43 | streaming: SyslineReader::drop_sysline(): Ok 176, Err 42
streaming: BlockReader::drop_block() : Ok 5, Err 3 | streaming: BlockReader::drop_block() : Ok 5, Err 4
streaming: LineReader::drop_line() : Ok 21, Err 4 | streaming: LineReader::drop_line() : Ok 22, Err 4
streaming: SyslineReader::drop_sysline(): Ok 24, Err 6 | streaming: SyslineReader::drop_sysline(): Ok 25, Err 5
streaming: BlockReader::drop_block() : Ok 6, Err 1 | streaming: BlockReader::drop_block() : Ok 5, Err 2
streaming: LineReader::drop_line() : Ok 10, Err 0 | streaming: LineReader::drop_line() : Ok 9, Err 0
streaming: SyslineReader::drop_sysline(): Ok 10, Err 1 | streaming: SyslineReader::drop_sysline(): Ok 9, Err 2
streaming: LineReader::drop_line() : Ok 11, Err 0 | streaming: LineReader::drop_line() : Ok 10, Err 0
streaming: SyslineReader::drop_sysline(): Ok 11, Err 0 | streaming: SyslineReader::drop_sysline(): Ok 10, Err 1
...
Different stderr ./tools/compare-current-and-expected/./logs/Debian11/alternatives.log.stderr
lines high : 11 | lines high : 12
streaming: BlockReader::drop_block() : Ok 6, Err 1 | streaming: BlockReader::drop_block() : Ok 5, Err 2
streaming: LineReader::drop_line() : Ok 4, Err 0 | streaming: LineReader::drop_line() : Ok 3, Err 0
streaming: SyslineReader::drop_sysline(): Ok 4, Err 3 | streaming: SyslineReader::drop_sysline(): Ok 3, Err 4
Different stderr ./tools/compare-current-and-expected/./logs/Debian11/kern.log.stderr
streaming: BlockReader::drop_block() : Ok 0, Err 1 | streaming: BlockReader::drop_block() : Ok 0, Err 1
streaming: LineReader::drop_line() : Ok 4, Err 3 | streaming: LineReader::drop_line() : Ok 2, Err 3
streaming: SyslineReader::drop_sysline(): Ok 7, Err 8 | streaming: SyslineReader::drop_sysline(): Ok 5, Err 10
Different stderr ./tools/compare-current-and-expected/./logs/Debian11/messages.stderr
streaming: BlockReader::drop_block() : Ok 0, Err 1 | streaming: BlockReader::drop_block() : Ok 0, Err 1
streaming: LineReader::drop_line() : Ok 3, Err 3 | streaming: LineReader::drop_line() : Ok 2, Err 3
streaming: SyslineReader::drop_sysline(): Ok 6, Err 9 | streaming: SyslineReader::drop_sysline(): Ok 5, Err 10
Different stderr ./tools/compare-current-and-expected/./logs/Debian11/user.log.stderr
streaming: BlockReader::drop_block() : Ok 1, Err 4 | streaming: BlockReader::drop_block() : Ok 1, Err 3
streaming: LineReader::drop_line() : Ok 7, Err 4 | streaming: LineReader::drop_line() : Ok 6, Err 4
streaming: SyslineReader::drop_sysline(): Ok 11, Err 7 | streaming: SyslineReader::drop_sysline(): Ok 10, Err 8
...
Environment:
Tested to occur back to 0.6.60. Did this by rebuilding old builds and then running compare-current-and-expected/update.sh then compare-current-and-expected/compare.sh.
for ver in 0.6.68 0.6.67 0.6.66 0.6.65 0.6.64 0.6.63 0.6.62 0.6.61 0.6.60; do
cargo clean
git checkout $ver
cargo build --release
cp -av ./target/release/s4 "./s4_$ver"
git checkout HEAD
PROGRAM="./s4_$ver" compare-current-and-expected/update.sh
PROGRAM="./s4_$ver" compare-current-and-expected/compare.sh || true
echo ver is $ver
doneOther
I suspect this has been occurring since drop blocks was implemented.
Also, why weren't these differences caught by test_SummaryBlockReader or test_SummaryLineReader or test_syslinereadersummary
jtmoon79 commented
tl;dr not a bug. It's due to multi-threaded checks of owners of the shared data structures
This occurs because there are two threads that have access to the same underlying data structures, the Sysline, Lines, and Block; the file processing thread and the main printing thread.
Being multi-threaded, the timing of when the file processing thread calls drop_data_try versus when the main printing thread will print and then be done with the Sysline instance, that will vary from run to run.