dynamorio
dynamorio copied to clipboard
DynamoRIO
ASSERT: various asserts when running fleetbench
Describe the bug We've been running the fleetbench tests internally and using the invariant checker to verify the results and have hit several asserts. This issue will cover the one we have managed to reproduce on the AArch64 CI machine with clang-12.
This assert manifests as:
Trace invariant failure in T1406984 at ref # 18217530 (1 instrs since timestamp 13343320636382108): Non-explicit control flow has no marker
Aborted (core dumped)
To Reproduce
wget https://github.com/DynamoRIO/dynamorio/releases/download/release_10.0.0/DynamoRIO-AArch64-Linux-10.0.0.tar.gz
tar -xzf DynamoRIO-AArch64-Linux-10.0.0.tar.gzwget https://github.com/bazelbuild/bazelisk/releases/download/v1.17.0/bazelisk-linux-arm64
chmod a+x bazelisk-linux-arm64git clone https://github.com/google/fleetbench.git
git -C fleetbench fetch origin v0.2.1
git -C fleetbench checkout v0.2.1
echo "build:opt --copt='-mcpu=cortex-A57'" >> fleetbench/.bazelrc
export DRUN=$(pwd)/DynamoRIO-AArch64-Linux-10.0.0/bin64/drrun
export OUTDIR=$(pwd)/output
mkdir ${OUTDIR}
cd fleetbench
GLIBC_TUNABLES=glibc.pthread.rseq=0 ../bazelisk-linux-arm64 run \
--run_under="${DRUN} -t drcachesim -offline -outdir ${OUTDIR} --" \
--config=clang --config=opt "fleetbench/swissmap:hot_swissmap_smoketest" && \
${DRUN} -t drcachesim -simulator_type invariant_checker \
-indir ${OUTDIR}/drmemtrace.hot_swissmap_smoketest.*
Versions
- These initial issues appeared in our head builds, but are reproducable with the latest release (10.0.0)
- These have been tested on ubuntu 20.04
Additional context
Additionally we are seeing the following asserts on our internal machines:
hot swissmap:
Trace invariant failure in T-1 at ref # 0 (0 instrs since timestamp 0): Serial schedule entry count does not match trace
cold swissmap:
Trace invariant failure in T1010 at ref # 89 (54 instrs since timestamp 13339766484591828): Timestamp does not increase monotonically
and when using sample windows:
fleetbench/tcmalloc:empirical_test:
Trace invariant failure in T7049 at ref # 3402633 (0 instrs since timestamp 13343308919845820): Syscall marker not placed after syscall instruction
fleetbench/swissmap:cold_swissmap_smoketest and fleetbench/swissmap:hot_swissmap_smoketest:
Trace invariant failure in T4279 at ref # 89 (54 instrs since timestamp 13343308657587587): Timestamp does not increase monotonically
fleetbench/tcmalloc:empirical_driver_test:
Trace invariant failure in TTrace invariant failure in T7919 at ref # Trace invariant failure in T7914 at ref # 9 (Trace invariant failure in T7954 at ref # 9 (0 instrs since timestamp 7945 at ref # 9 (0 instrs since timestamp 133433090606881269): 013343309095144172 instrs since timestamp 13343308960112710): An unfiltered thread should have at least 1 instruction (
): An unfiltered thread should have at least 1 instructionAn unfiltered thread should have at least 1 instruction0Trace invariant failure in T7929 at ref # 9 (0
Could you paste in the human readable trace view before and after each error? E.g. the first one says failure in T1406984 at ref # 18217530 so run with -simulator_type view -skip_refs 18217515 -sim_refs 18217540 or similar and paste the result.
For the "Serial schedule entry count does not match trace" invariant error, does the invariant checker has PR6366? https://github.com/DynamoRIO/dynamorio/pull/6366
@ivankyluk , I believe so. I was testing against the head for those but it has been a while since I first saw them. I can try and reproduce with HEAD and see if it is still there
@derekbruening , I believe this is what you're after:
$ ${DRUN} -t drcachesim -simulator_type invariant_checker -indir ${OUTDIR}/drmemtrace.hot_swissmap_smoketest.*
Trace invariant failure in T2687566 at ref # 18217530 (1 instrs since timestamp 13343835981829741): Non-explicit control flow has no marker
Aborted (core dumped)
$ ${DRUN} -t drcachesim -simulator_type view -indir ${OUTDIR}/drmemtrace.hot_swissmap_smoketest.* -skip_refs 18217500 -sim_refs 100
Output format:
<--record#-> <--instr#->: <---tid---> <record details>
------------------------------------------------------------
18217501 13270113: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609621c 910003fd add %sp $0x0000 lsl $0x00 -> %x29
18217502 13270114: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096220 f90017e0 str %x0 -> +0x28(%sp)[8byte]
18217503 13270114: 2687566 write 8 byte(s) @ 0x0000ffffce88dab8 by PC 0x0000ffff86096220
18217504 13270115: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096224 d0000120 adrp <rel> 0x0000ffff860bc000 -> %x0
18217505 13270116: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096228 f9000bf3 str %x19 -> +0x10(%sp)[8byte]
18217506 13270116: 2687566 write 8 byte(s) @ 0x0000ffffce88daa0 by PC 0x0000ffff86096228
18217507 13270117: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609622c f94017f3 ldr +0x28(%sp)[8byte] -> %x19
18217508 13270117: 2687566 read 8 byte(s) @ 0x0000ffffce88dab8 by PC 0x0000ffff8609622c
18217509 13270118: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096230 f9437801 ldr +0x06f0(%x0)[8byte] -> %x1
18217510 13270118: 2687566 read 8 byte(s) @ 0x0000ffff860bc6f0 by PC 0x0000ffff86096230
18217511 13270119: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096234 f9400262 ldr (%x19)[8byte] -> %x2
18217512 13270119: 2687566 read 8 byte(s) @ 0x0000fffd85848580 by PC 0x0000ffff86096234
18217513 13270120: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096238 cb0103e1 sub %xzr %x1 lsl $0x00 -> %x1
18217514 13270121: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609623c f9424a60 ldr +0x0490(%x19)[8byte] -> %x0
18217515 13270121: 2687566 read 8 byte(s) @ 0x0000fffd85848a10 by PC 0x0000ffff8609623c
18217516 13270122: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096240 f9424e63 ldr +0x0498(%x19)[8byte] -> %x3
18217517 13270122: 2687566 read 8 byte(s) @ 0x0000fffd85848a18 by PC 0x0000ffff86096240
18217518 13270123: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096244 8b000042 add %x2 %x0 lsl $0x00 -> %x2
18217519 13270124: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096248 8a010040 and %x2 %x1 lsl $0x00 -> %x0
18217520 13270125: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609624c 8b030042 add %x2 %x3 lsl $0x00 -> %x2
18217521 13270126: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096250 8a010041 and %x2 %x1 lsl $0x00 -> %x1
18217522 13270127: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096254 eb01001f subs %x0 %x1 lsl $0x00 -> %xzr
18217523 13270128: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096258 54000081 b.ne $0x0000ffff86096268 (taken)
18217524 13270129: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096268 cb000021 sub %x1 %x0 lsl $0x00 -> %x1
18217525 13270130: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609626c 52800022 movz $0x0001 lsl $0x00 -> %w2
18217526 13270131: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096270 94003324 bl $0x0000ffff860a2f00 -> %x30
18217527 13270132: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f00 d2801c48 movz $0x00e2 lsl $0x00 -> %x8
18217528 13270132: 2687566 <marker: timestamp 13343835981829741>
18217529 13270132: 2687566 <marker: tid 2687566 on core 27>
18217530 13270133: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f08 b13ffc1f adds %x0 $0x0fff lsl $0x00 -> %xzr
18217531 13270134: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f0c 54000042 b.cs $0x0000ffff860a2f14 (untaken)
18217532 13270135: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f10 d65f03c0 ret %x30 (target 0xffff86096274)
18217533 13270136: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096274 36ffff40 tbz $0x0000ffff8609625c %w0 $0x1f (taken)
18217534 13270137: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609625c f9400bf3 ldr +0x10(%sp)[8byte] -> %x19
18217535 13270137: 2687566 read 8 byte(s) @ 0x0000ffffce88daa0 by PC 0x0000ffff8609625c
18217536 13270138: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096260 a8c37bfd ldp (%sp)[16byte] %sp $0x0000000000000030 -> %x29 %x30 %sp
18217537 13270138: 2687566 read 16 byte(s) @ 0x0000ffffce88da90 by PC 0x0000ffff86096260
18217538 13270139: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096264 d65f03c0 ret %x30 (target 0xffff86096ea8)
18217539 13270140: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096ea8 910003bf add %x29 $0x0000 lsl $0x00 -> %sp
18217540 13270141: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eac a94153f3 ldp +0x10(%sp)[16byte] -> %x19 %x20
18217541 13270141: 2687566 read 16 byte(s) @ 0x0000ffffce88dae0 by PC 0x0000ffff86096eac
18217542 13270142: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eb0 a9425bf5 ldp +0x20(%sp)[16byte] -> %x21 %x22
18217543 13270142: 2687566 read 16 byte(s) @ 0x0000ffffce88daf0 by PC 0x0000ffff86096eb0
18217544 13270143: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eb4 a94363f7 ldp +0x30(%sp)[16byte] -> %x23 %x24
18217545 13270143: 2687566 read 16 byte(s) @ 0x0000ffffce88db00 by PC 0x0000ffff86096eb4
18217546 13270144: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eb8 a9446bf9 ldp +0x40(%sp)[16byte] -> %x25 %x26
18217547 13270144: 2687566 read 16 byte(s) @ 0x0000ffffce88db10 by PC 0x0000ffff86096eb8
18217548 13270145: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096ebc a94573fb ldp +0x50(%sp)[16byte] -> %x27 %x28
18217549 13270145: 2687566 read 16 byte(s) @ 0x0000ffffce88db20 by PC 0x0000ffff86096ebc
18217550 13270146: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096ec0 a8d27bfd ldp (%sp)[16byte] %sp $0x0000000000000120 -> %x29 %x30 %sp
18217551 13270146: 2687566 read 16 byte(s) @ 0x0000ffffce88dad0 by PC 0x0000ffff86096ec0
18217552 13270147: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096ec4 d65f03c0 ret %x30 (target 0xffff8608ed90)
18217553 13270148: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed90 f9423260 ldr +0x0460(%x19)[8byte] -> %x0
18217554 13270148: 2687566 read 8 byte(s) @ 0x0000fffd858489e0 by PC 0x0000ffff8608ed90
18217555 13270149: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed94 b4fffd40 cbz $0x0000ffff8608ed3c %x0 (taken)
18217556 13270150: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed3c d1002318 sub %x24 $0x0008 lsl $0x00 -> %x24
18217557 13270151: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed40 b100231f adds %x24 $0x0008 lsl $0x00 -> %xzr
18217558 13270152: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed44 540003e0 b.eq $0x0000ffff8608edc0 (untaken)
18217559 13270153: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed48 f941fee0 ldr +0x03f8(%x23)[8byte] -> %x0
18217560 13270153: 2687566 read 8 byte(s) @ 0x0000ffff860be5f8 by PC 0x0000ffff8608ed48
18217561 13270154: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed4c f8786813 ldr (%x0,%x24)[8byte] -> %x19
18217562 13270154: 2687566 read 8 byte(s) @ 0x0000fffd84e200d8 by PC 0x0000ffff8608ed4c
18217563 13270155: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed50 f9401e60 ldr +0x38(%x19)[8byte] -> %x0
18217564 13270155: 2687566 read 8 byte(s) @ 0x0000fffd85847ea8 by PC 0x0000ffff8608ed50
18217565 13270156: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed54 f9400400 ldr +0x08(%x0)[8byte] -> %x0
18217566 13270156: 2687566 read 8 byte(s) @ 0x0000fffd85848328 by PC 0x0000ffff8608ed54
18217567 13270157: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed58 b50002c0 cbnz $0x0000ffff8608edb0 %x0 (untaken)
18217568 13270158: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed5c 394d3a60 ldrb +0x034e(%x19)[1byte] -> %w0
18217569 13270158: 2687566 read 1 byte(s) @ 0x0000fffd858481be by PC 0x0000ffff8608ed5c
18217570 13270159: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed60 f94067a1 ldr +0xc8(%x29)[8byte] -> %x1
18217571 13270159: 2687566 read 8 byte(s) @ 0x0000ffffce88dcc8 by PC 0x0000ffff8608ed60
18217572 13270160: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed64 121f7800 and %w0 $0xfffffffe -> %w0
18217573 13270161: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed68 390d3a60 strb %w0 -> +0x034e(%x19)[1byte]
18217574 13270161: 2687566 write 1 byte(s) @ 0x0000fffd858481be by PC 0x0000ffff8608ed68
18217575 13270162: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed6c eb01027f subs %x19 %x1 lsl $0x00 -> %xzr
18217576 13270163: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed70 54000100 b.eq $0x0000ffff8608ed90 (untaken)
18217577 13270164: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed74 b94046c0 ldr +0x44(%x22)[4byte] -> %w0
18217578 13270164: 2687566 read 4 byte(s) @ 0x0000ffff860bc71c by PC 0x0000ffff8608ed74
18217579 13270165: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed78 2a1c03e3 orr %wzr %w28 lsl $0x00 -> %w3
18217580 13270166: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed7c f941e261 ldr +0x03c0(%x19)[8byte] -> %x1
18217581 13270166: 2687566 read 8 byte(s) @ 0x0000fffd85848230 by PC 0x0000ffff8608ed7c
18217582 13270167: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed80 7100001f subs %w0 $0x0000 lsl $0x00 -> %wzr
18217583 13270168: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed84 1a9f07e2 csinc %wzr %wzr eq -> %w2
18217584 13270169: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed88 aa1303e0 orr %xzr %x19 lsl $0x00 -> %x0
18217585 13270170: 2687566 ifetch 4 byte(s) @ 0x0000ffff8608ed8c 94001d77 bl $0x0000ffff86096368 -> %x30
18217586 13270171: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096368 a9ae7bfd stp %x29 %x30 %sp $0xfffffffffffffee0 -> -0x0120(%sp)[16byte] %sp
18217587 13270171: 2687566 write 16 byte(s) @ 0x0000ffffce88dad0 by PC 0x0000ffff86096368
18217588 13270172: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609636c 910003fd add %sp $0x0000 lsl $0x00 -> %x29
18217589 13270173: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096370 a90153f3 stp %x19 %x20 -> +0x10(%sp)[16byte]
18217590 13270173: 2687566 write 16 byte(s) @ 0x0000ffffce88dae0 by PC 0x0000ffff86096370
18217591 13270174: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096374 2a0203f3 orr %wzr %w2 lsl $0x00 -> %w19
18217592 13270175: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096378 aa0003f4 orr %xzr %x0 lsl $0x00 -> %x20
18217593 13270176: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609637c a9025bf5 stp %x21 %x22 -> +0x20(%sp)[16byte]
18217594 13270176: 2687566 write 16 byte(s) @ 0x0000ffffce88daf0 by PC 0x0000ffff8609637c
18217595 13270177: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096380 aa0103f6 orr %xzr %x1 lsl $0x00 -> %x22
18217596 13270178: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096384 12000055 and %w2 $0x00000001 -> %w21
18217597 13270179: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096388 a90363f7 stp %x23 %x24 -> +0x30(%sp)[16byte]
18217598 13270179: 2687566 write 16 byte(s) @ 0x0000ffffce88db00 by PC 0x0000ffff86096388
18217599 13270180: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609638c a9046bf9 stp %x25 %x26 -> +0x40(%sp)[16byte]
18217600 13270180: 2687566 write 16 byte(s) @ 0x0000ffffce88db10 by PC 0x0000ffff8609638c
- What instruction is at 0x0000ffff860a2f04 (the missing one) (may need to look in the binary)?
- (Does not look like an rseq region: presumably there is no rseq entry marker earlier, as there are stores in between.)
- What we would like is the
-verbose 4output from raw2trace for that sequence with the missing 0x...2f04 instruction: maybe running raw2trace at that verbosity for the whole run is feasible and then extracting that part.
Took me a little while to find the missing instruction as it's actually in the libraries rather than the binary itself. It seems that
18217527 13270132: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f00 d2801c48 movz $0x00e2 lsl $0x00 -> %x8
18217528 13270132: 2687566 <marker: timestamp 13343835981829741>
18217529 13270132: 2687566 <marker: tid 2687566 on core 27>
18217530 13270133: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f08 b13ffc1f adds %x0 $0x0fff lsl $0x00 -> %xzr
18217531 13270134: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f0c 54000042 b.cs $0x0000ffff860a2f14 (untaken)
18217532 13270135: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f10 d65f03c0 ret %x30 (target 0xffff86096274)
is matched by
17f00: d2801c48 mov x8, #0xe2 // #226
17f04: d4000001 svc #0x0
17f08: b13ffc1f cmn x0, #0xfff
17f0c: 54000042 b.cs 17f14 <_dl_catch_error@@GLIBC_PRIVATE+0x13c4> // b.hs, b.nlast
17f10: d65f03c0 ret
in /lib/ld-linux-aarch64.so.1 meaning that the missing instruction is svc #0x0
I've cranked up the verbosity and extracted 20 lines before and after that site, but there doesn't appear to be much more in the way of useful information:
$ ${DRUN} -t drcachesim -simulator_type view -indir ${OUTDIR}/drmemtrace.hot_swissmap_smoketest.* -verbose 4 2>&1 | grep -B 20 -A 20 18217527
18217507 13270117: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609622c f94017f3 ldr +0x28(%sp)[8byte] -> %x19
18217508 13270117: 2687566 read 8 byte(s) @ 0x0000ffffce88dab8 by PC 0x0000ffff8609622c
18217509 13270118: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096230 f9437801 ldr +0x06f0(%x0)[8byte] -> %x1
18217510 13270118: 2687566 read 8 byte(s) @ 0x0000ffff860bc6f0 by PC 0x0000ffff86096230
18217511 13270119: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096234 f9400262 ldr (%x19)[8byte] -> %x2
18217512 13270119: 2687566 read 8 byte(s) @ 0x0000fffd85848580 by PC 0x0000ffff86096234
18217513 13270120: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096238 cb0103e1 sub %xzr %x1 lsl $0x00 -> %x1
18217514 13270121: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609623c f9424a60 ldr +0x0490(%x19)[8byte] -> %x0
18217515 13270121: 2687566 read 8 byte(s) @ 0x0000fffd85848a10 by PC 0x0000ffff8609623c
18217516 13270122: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096240 f9424e63 ldr +0x0498(%x19)[8byte] -> %x3
18217517 13270122: 2687566 read 8 byte(s) @ 0x0000fffd85848a18 by PC 0x0000ffff86096240
18217518 13270123: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096244 8b000042 add %x2 %x0 lsl $0x00 -> %x2
18217519 13270124: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096248 8a010040 and %x2 %x1 lsl $0x00 -> %x0
18217520 13270125: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609624c 8b030042 add %x2 %x3 lsl $0x00 -> %x2
18217521 13270126: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096250 8a010041 and %x2 %x1 lsl $0x00 -> %x1
18217522 13270127: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096254 eb01001f subs %x0 %x1 lsl $0x00 -> %xzr
18217523 13270128: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096258 54000081 b.ne $0x0000ffff86096268 (taken)
18217524 13270129: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096268 cb000021 sub %x1 %x0 lsl $0x00 -> %x1
18217525 13270130: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609626c 52800022 movz $0x0001 lsl $0x00 -> %w2
18217526 13270131: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096270 94003324 bl $0x0000ffff860a2f00 -> %x30
18217527 13270132: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f00 d2801c48 movz $0x00e2 lsl $0x00 -> %x8
18217528 13270132: 2687566 <marker: timestamp 13343835981829741>
18217529 13270132: 2687566 <marker: tid 2687566 on core 27>
18217530 13270133: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f08 b13ffc1f adds %x0 $0x0fff lsl $0x00 -> %xzr
18217531 13270134: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f0c 54000042 b.cs $0x0000ffff860a2f14 (untaken)
18217532 13270135: 2687566 ifetch 4 byte(s) @ 0x0000ffff860a2f10 d65f03c0 ret %x30 (target 0xffff86096274)
18217533 13270136: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096274 36ffff40 tbz $0x0000ffff8609625c %w0 $0x1f (taken)
18217534 13270137: 2687566 ifetch 4 byte(s) @ 0x0000ffff8609625c f9400bf3 ldr +0x10(%sp)[8byte] -> %x19
18217535 13270137: 2687566 read 8 byte(s) @ 0x0000ffffce88daa0 by PC 0x0000ffff8609625c
18217536 13270138: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096260 a8c37bfd ldp (%sp)[16byte] %sp $0x0000000000000030 -> %x29 %x30 %sp
18217537 13270138: 2687566 read 16 byte(s) @ 0x0000ffffce88da90 by PC 0x0000ffff86096260
18217538 13270139: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096264 d65f03c0 ret %x30 (target 0xffff86096ea8)
18217539 13270140: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096ea8 910003bf add %x29 $0x0000 lsl $0x00 -> %sp
18217540 13270141: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eac a94153f3 ldp +0x10(%sp)[16byte] -> %x19 %x20
18217541 13270141: 2687566 read 16 byte(s) @ 0x0000ffffce88dae0 by PC 0x0000ffff86096eac
18217542 13270142: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eb0 a9425bf5 ldp +0x20(%sp)[16byte] -> %x21 %x22
18217543 13270142: 2687566 read 16 byte(s) @ 0x0000ffffce88daf0 by PC 0x0000ffff86096eb0
18217544 13270143: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eb4 a94363f7 ldp +0x30(%sp)[16byte] -> %x23 %x24
18217545 13270143: 2687566 read 16 byte(s) @ 0x0000ffffce88db00 by PC 0x0000ffff86096eb4
18217546 13270144: 2687566 ifetch 4 byte(s) @ 0x0000ffff86096eb8 a9446bf9 ldp +0x40(%sp)[16byte] -> %x25 %x26
18217547 13270144: 2687566 read 16 byte(s) @ 0x0000ffffce88db10 by PC 0x0000ffff86096eb8
```
You're running the view tool there: my suggestion was to run raw2trace, re-generating the final trace from the raw data. The raw data has just one record for the whole basic block, so omitting the svc will be visible there: either it deliberately truncated the block or the raw record has the wrong instruction count. Something like clients/bin64/drraw2trace -indir <rawdir> -out /tmp -verbose 4.
The output grew to over 200GB, but I managed to extract the logs here:
[drmemtrace]: Appending 2 instrs in bb 0xfffd7fb1ef00 in mod 7 +0x17f00 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
[drmemtrace]: 0x0000ffff860a2f00 d2801c48 movz $0x00e2 lsl $0x00 -> %x8
Appended instr fetch for original 0x44f5a4
[drmemtrace]: [drmemtrace]: Appending delayed branch type=14 pc=0xffff86090dd0 decode=0xfffd7fb0cdd0 target=0xffff860a2f00 for thread 0
Appended memref type write (1) size 8 to 0xfffd84df7ea8
[drmemtrace]: [drmemtrace]: Appending delayed branch tagalong entry type encoding (47) for thread 0
Chunk instr count is now 52165
[drmemtrace]: 0x000000000044f5a8 eb13011f subs %x8 %x19 lsl $0x00 -> %xzr
Chunk instr count is now 40507
[drmemtrace]: Appended encoding entry for 0xfffd7fb1ef00 sz=4 0xd2801c48...
[drmemtrace]: Appended instr fetch for original 0xffff860a2f00
[drmemtrace]: [drmemtrace]: Appended instr fetch for original 0x44f5a8
[drmemtrace]: Chunk instr count is now 52166
Chunk instr count is now 40508
0x000000000044f5ac f9000589 str %x9 -> +0x08(%x12)[8byte]
0x0000ffff860a2f04 d4000001 svc $0x0000
[drmemtrace]: Appended instr fetch for original 0x44f5ac
[drmemtrace]: Filling in elided addr with remembered x12: 0xfffd84df7ea8
[drmemtrace]: Appended memref type write (1) size 8 to 0xfffd84df7eb0
[drmemtrace]: Appended encoding entry for 0xfffd7fb1ef04 sz=4 0xd4000001...
[drmemtrace]: Appended instr fetch for original 0xffff860a2f04
[drmemtrace]: Chunk instr count is now 52167
[drmemtrace]: 0x000000000044f5b0 54fffea0 b.eq $0x000000000044f584
Chunk instr count is now 40509
[drmemtrace]: [drmemtrace]: Appended instr fetch for original
0x44f5b0
[drmemtrace]: Delaying 1 entries for decode=0x44f5b0
[drmemtrace]: Remembered delayed branch decode=0x44f5b0 target
=0x44f584
Appended marker type 25 value 0xe2
[drmemtrace]: Chunk instr count is now 40509
[drmemtrace]: [drmemtrace]: Appending 11 instrs in bb 0x44f5b4
in mod 0 +0x4f5b4 = /home/jwarburton/.cache/bazel/_bazel_jwar
burton/0baaf7a1c913bb84a799462e0d4aa687/execroot/com_google_fl
eetbench/bazel-out/aarch64-opt-clang/bin/fleetbench/swissmap/h
ot_swissmap_smoketest
Thread 2687566 timestamp 0x002f6825eba0e383
0x000000000044f5b4 29402d0a ldp (%x8)[8byte] -> %w10 %
w11
That must be at least two threads interleaved together? It shows the svc at *f04. Could it be in an rseq region? More context is needed. If you search above do you see any reference to "rseq"? Especially "Reached rseq entry...buffering all output".
To avoid the concurrent lines could run with just one worker; or limit to just the one app thread.
rseq does not appear to be mentioned in the logs above that instruction
The instruction appears a few times in the verbose log, here's the first:
[drmemtrace]: Chunk instr count is now 40471
0x0000ffff86090d6c b900a3ac str %w12 -> +0xa0(%x29)[4byte]
[drmemtrace]: Appended encoding entry for 0xfffd8623ad6c sz=4 0xb900a3ac...
[drmemtrace]: Appended instr fetch for original 0xffff86090d6c
[drmemtrace]: Filling in elided addr with remembered x29: 0xffffce88cf60
[drmemtrace]: Appended memref type write (1) size 4 to 0xffffce88d000
[drmemtrace]: Chunk instr count is now 40472
0x0000ffff86090d70 94004844 bl $0x0000ffff860a2e80 -> %x30
[drmemtrace]: Appended encoding entry for 0xfffd8623ad70 sz=4 0x94004844...
[drmemtrace]: Appended instr fetch for original 0xffff86090d70
[drmemtrace]: Delaying 2 entries for decode=0xfffd8623ad70
[drmemtrace]: Remembered delayed branch decode=0xfffd8623ad70 target=0xffff860a2e80
[drmemtrace]: Appending 2 instrs in bb 0xfffd8624ce80 in mod 7 +0x17e80 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff860a2e80 f2402cbf ands %x5 $0x0000000000000fff -> %xzr
[drmemtrace]: Appending delayed branch type=14 pc=0xffff86090d70 decode=0xfffd8623ad70 target=0xffff860a2e80 for thread 0
[drmemtrace]: Appending delayed branch tagalong entry type encoding (47) for thread 0
[drmemtrace]: Chunk instr count is now 40473
[drmemtrace]: Appended instr fetch for original 0xffff860a2e80
[drmemtrace]: Chunk instr count is now 40474
0x0000ffff860a2e84 54000121 b.ne $0x0000ffff860a2ea8
[drmemtrace]: Appended instr fetch for original 0xffff860a2e84
[drmemtrace]: Delaying 1 entries for decode=0xfffd8624ce84
[drmemtrace]: Remembered delayed branch decode=0xfffd8624ce84 target=0xffff860a2ea8
[drmemtrace]: Appending 5 instrs in bb 0xfffd8624ce88 in mod 7 +0x17e88 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff860a2e88 93407c42 sbfm %x2 $0x00 $0x1f -> %x2
[drmemtrace]: Appending delayed branch type=49 pc=0xffff860a2e84 decode=0xfffd8624ce84 target=0xffff860a2ea8 for thread 0
[drmemtrace]: Chunk instr count is now 40475
[drmemtrace]: Appended instr fetch for original 0xffff860a2e88
[drmemtrace]: Chunk instr count is now 40476
0x0000ffff860a2e8c 93407c63 sbfm %x3 $0x00 $0x1f -> %x3
[drmemtrace]: Appended instr fetch for original 0xffff860a2e8c
[drmemtrace]: Chunk instr count is now 40477
0x0000ffff860a2e90 93407c84 sbfm %x4 $0x00 $0x1f -> %x4
[drmemtrace]: Appended instr fetch for original 0xffff860a2e90
[drmemtrace]: Chunk instr count is now 40478
0x0000ffff860a2e94 d2801bc8 movz $0x00de lsl $0x00 -> %x8
[drmemtrace]: Appended instr fetch for original 0xffff860a2e94
[drmemtrace]: Chunk instr count is now 40479
0x0000ffff860a2e98 d4000001 svc $0x0000
[drmemtrace]: Appended instr fetch for original 0xffff860a2e98
[drmemtrace]: Chunk instr count is now 40480
[drmemtrace]: Appended marker type 25 value 0xde
[drmemtrace]: Chunk instr count is now 40480
[drmemtrace]: Thread 2687566 timestamp 0x002f6825eba0e216
[drmemtrace]: Chunk instr count is now 40480
[drmemtrace]: Appended marker type 3 value 0x1b
[drmemtrace]: Chunk instr count is now 40480
[drmemtrace]: Appending 2 instrs in bb 0xfffd8624ce9c in mod 7 +0x17e9c = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff860a2e9c b140041f adds %x0 $0x0001 lsl $0x0c -> %xzr
[drmemtrace]: Appended instr fetch for original 0xffff860a2e9c
[drmemtrace]: Chunk instr count is now 40481
0x0000ffff860a2ea0 540000e8 b.hi $0x0000ffff860a2ebc
[drmemtrace]: Appended instr fetch for original 0xffff860a2ea0
[drmemtrace]: Delaying 1 entries for decode=0xfffd8624cea0
[drmemtrace]: Remembered delayed branch decode=0xfffd8624cea0 target=0xffff860a2ebc
[drmemtrace]: Appending 1 instrs in bb 0xfffd8624cea4 in mod 7 +0x17ea4 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff860a2ea4 d65f03c0 ret %x30
[drmemtrace]: Appended instr fetch for original 0xffff860a2ea4
[drmemtrace]: Delaying 1 entries for decode=0xfffd8624cea4
[drmemtrace]: Remembered delayed branch decode=0xfffd8624cea4 target=(nil)
[drmemtrace]: Appending 8 instrs in bb 0xfffd8623ad74 in mod 7 +0x5d74 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff86090d74 f901c360 str %x0 -> +0x0380(%x27)[8byte]
[drmemtrace]: Inserted indirect branch target 0xffff86090d74
[drmemtrace]: Appending delayed branch type=16 pc=0xffff860a2ea4 decode=0xfffd8624cea4 target=(nil) for thread 0
[drmemtrace]: Appending delayed branch type=49 pc=0xffff860a2ea0 decode=0xfffd8624cea0 target=0xffff860a2ebc for thread 0
[drmemtrace]: Chunk instr count is now 40483
[drmemtrace]: Appended encoding entry for 0xfffd8623ad74 sz=4 0xf901c360...
[drmemtrace]: Appended instr fetch for original 0xffff86090d74
[drmemtrace]: Appended memref type write (1) size 8 to 0xffff86080860
[drmemtrace]: Chunk instr count is now 40484
0x0000ffff86090d78 b100041f adds %x0 $0x0001 lsl $0x00 -> %xzr
[drmemtrace]: Appended encoding entry for 0xfffd8623ad78 sz=4 0xb100041f...
[drmemtrace]: Appended instr fetch for original 0xffff86090d78
[drmemtrace]: Chunk instr count is now 40485
0x0000ffff86090d7c b94093a7 ldr +0x90(%x29)[4byte] -> %w7
[drmemtrace]: Appended encoding entry for 0xfffd8623ad7c sz=4 0xb94093a7...
[drmemtrace]: Appended instr fetch for original 0xffff86090d7c
[drmemtrace]: Appended memref type read (0) size 4 to 0xffffce88cff0
[drmemtrace]: Chunk instr count is now 40486
0x0000ffff86090d80 b940a3ac ldr +0xa0(%x29)[4byte] -> %w12
[drmemtrace]: Appended encoding entry for 0xfffd8623ad80 sz=4 0xb940a3ac...
[drmemtrace]: Appended instr fetch for original 0xffff86090d80
[drmemtrace]: Filling in elided addr with remembered x29: 0xffffce88cf60
[drmemtrace]: Appended memref type read (0) size 4 to 0xffffce88d000
[drmemtrace]: Chunk instr count is now 40487
0x0000ffff86090d84 a947aba6 ldp +0x78(%x29)[16byte] -> %x6 %x10
[drmemtrace]: Appended encoding entry for 0xfffd8623ad84 sz=4 0xa947aba6...
[drmemtrace]: Appended instr fetch for original 0xffff86090d84
[drmemtrace]: Filling in elided addr with remembered x29: 0xffffce88cf60
[drmemtrace]: Appended memref type read (0) size 16 to 0xffffce88cfd8
[drmemtrace]: Chunk instr count is now 40488
0x0000ffff86090d88 f94047a9 ldr +0x88(%x29)[8byte] -> %x9
[drmemtrace]: Appended encoding entry for 0xfffd8623ad88 sz=4 0xf94047a9...
[drmemtrace]: Appended instr fetch for original 0xffff86090d88
[drmemtrace]: Filling in elided addr with remembered x29: 0xffffce88cf60
[drmemtrace]: Appended memref type read (0) size 8 to 0xffffce88cfe8
[drmemtrace]: Chunk instr count is now 40489
0x0000ffff86090d8c f9404fab ldr +0x98(%x29)[8byte] -> %x11
[drmemtrace]: Appended encoding entry for 0xfffd8623ad8c sz=4 0xf9404fab...
[drmemtrace]: Appended instr fetch for original 0xffff86090d8c
[drmemtrace]: Filling in elided addr with remembered x29: 0xffffce88cf60
[drmemtrace]: Appended memref type read (0) size 8 to 0xffffce88cff8
[drmemtrace]: Chunk instr count is now 40490
0x0000ffff86090d90 54000b60 b.eq $0x0000ffff86090efc
[drmemtrace]: Appended encoding entry for 0xfffd8623ad90 sz=4 0x54000b60...
[drmemtrace]: Appended instr fetch for original 0xffff86090d90
[drmemtrace]: Delaying 2 entries for decode=0xfffd8623ad90
[drmemtrace]: Remembered delayed branch decode=0xfffd8623ad90 target=0xffff86090efc
[drmemtrace]: Appending 5 instrs in bb 0xfffd8623ad94 in mod 7 +0x5d94 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff86090d94 cb0b000b sub %x0 %x11 lsl $0x00 -> %x11
[drmemtrace]: Appending delayed branch type=49 pc=0xffff86090d90 decode=0xfffd8623ad90 target=0xffff86090efc for thread 0
[drmemtrace]: Appending delayed branch tagalong entry type encoding (47) for thread 0
[drmemtrace]: Chunk instr count is now 40491
[drmemtrace]: Appended encoding entry for 0xfffd8623ad94 sz=4 0xcb0b000b...
[drmemtrace]: Appended instr fetch for original 0xffff86090d94
[drmemtrace]: Chunk instr count is now 40492
0x0000ffff86090d98 8b190000 add %x0 %x25 lsl $0x00 -> %x0
[drmemtrace]: Appended encoding entry for 0xfffd8623ad98 sz=4 0x8b190000...
[drmemtrace]: Appended instr fetch for original 0xffff86090d98
[drmemtrace]: Chunk instr count is now 40493
0x0000ffff86090d9c f900036b str %x11 -> (%x27)[8byte]
[drmemtrace]: Appended encoding entry for 0xfffd8623ad9c sz=4 0xf900036b...
[drmemtrace]: Appended instr fetch for original 0xffff86090d9c
[drmemtrace]: Appended memref type write (1) size 8 to 0xffff860804e0
[drmemtrace]: Chunk instr count is now 40494
0x0000ffff86090da0 f901c760 str %x0 -> +0x0388(%x27)[8byte]
[drmemtrace]: Appended encoding entry for 0xfffd8623ada0 sz=4 0xf901c760...
[drmemtrace]: Appended instr fetch for original 0xffff86090da0
[drmemtrace]: Filling in elided addr with remembered x27: 0xffff860804e0
[drmemtrace]: Appended memref type write (1) size 8 to 0xffff86080868
[drmemtrace]: Chunk instr count is now 40495
0x0000ffff86090da4 34000207 cbz $0x0000ffff86090de4 %w7
[drmemtrace]: Appended encoding entry for 0xfffd8623ada4 sz=4 0x34000207...
[drmemtrace]: Appended instr fetch for original 0xffff86090da4
[drmemtrace]: Delaying 2 entries for decode=0xfffd8623ada4
[drmemtrace]: Remembered delayed branch decode=0xfffd8623ada4 target=0xffff86090de4
[drmemtrace]: Appending 11 instrs in bb 0xfffd8623ada8 in mod 7 +0x5da8 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff86090da8 8b180703 add %x24 %x24 lsl $0x01 -> %x3
[drmemtrace]: Appending delayed branch type=49 pc=0xffff86090da4 decode=0xfffd8623ada4 target=0xffff86090de4 for thread 0
[drmemtrace]: Appending delayed branch tagalong entry type encoding (47) for thread 0
[drmemtrace]: Chunk instr count is now 40496
[drmemtrace]: Appended encoding entry for 0xfffd8623ada8 sz=4 0x8b180703...
[drmemtrace]: Appended instr fetch for original 0xffff86090da8
[drmemtrace]: Chunk instr count is now 40497
0x0000ffff86090dac 52800002 movz $0x0000 lsl $0x00 -> %w2
[drmemtrace]: Appended encoding entry for 0xfffd8623adac sz=4 0x52800002...
[drmemtrace]: Appended instr fetch for original 0xffff86090dac
[drmemtrace]: Chunk instr count is now 40498
0x0000ffff86090db0 f9400741 ldr +0x08(%x26)[8byte] -> %x1
[drmemtrace]: Appended encoding entry for 0xfffd8623adb0 sz=4 0xf9400741...
[drmemtrace]: Appended instr fetch for original 0xffff86090db0
[drmemtrace]: Appended memref type read (0) size 8 to 0xffffce88cde8
[drmemtrace]: Chunk instr count is now 40499
0x0000ffff86090db4 8b031343 add %x26 %x3 lsl $0x04 -> %x3
[drmemtrace]: Appended encoding entry for 0xfffd8623adb4 sz=4 0x8b031343...
[drmemtrace]: Appended instr fetch for original 0xffff86090db4
[drmemtrace]: Chunk instr count is now 40500
0x0000ffff86090db8 a908aba6 stp %x6 %x10 -> +0x88(%x29)[16byte]
[drmemtrace]: Appended encoding entry for 0xfffd8623adb8 sz=4 0xa908aba6...
[drmemtrace]: Appended instr fetch for original 0xffff86090db8
[drmemtrace]: Appended memref type write (1) size 16 to 0xffffce88cfe8
[drmemtrace]: Chunk instr count is now 40501
0x0000ffff86090dbc 8b010160 add %x11 %x1 lsl $0x00 -> %x0
[drmemtrace]: Appended encoding entry for 0xfffd8623adbc sz=4 0x8b010160...
[drmemtrace]: Appended instr fetch for original 0xffff86090dbc
[drmemtrace]: Chunk instr count is now 40502
0x0000ffff86090dc0 f85d0063 ldur -0x30(%x3)[8byte] -> %x3
[drmemtrace]: Appended encoding entry for 0xfffd8623adc0 sz=4 0xf85d0063...
[drmemtrace]: Appended instr fetch for original 0xffff86090dc0
[drmemtrace]: Appended memref type read (0) size 8 to 0xffffce88ce10
[drmemtrace]: Chunk instr count is now 40503
0x0000ffff86090dc4 f9004fa9 str %x9 -> +0x98(%x29)[8byte]
[drmemtrace]: Appended encoding entry for 0xfffd8623adc4 sz=4 0xf9004fa9...
[drmemtrace]: Appended instr fetch for original 0xffff86090dc4
[drmemtrace]: Filling in elided addr with remembered x29: 0xffffce88cf60
[drmemtrace]: Appended memref type write (1) size 8 to 0xffffce88cff8
[drmemtrace]: Chunk instr count is now 40504
0x0000ffff86090dc8 b900a3ac str %w12 -> +0xa0(%x29)[4byte]
[drmemtrace]: Appended encoding entry for 0xfffd8623adc8 sz=4 0xb900a3ac...
[drmemtrace]: Appended instr fetch for original 0xffff86090dc8
[drmemtrace]: Filling in elided addr with remembered x29: 0xffffce88cf60
[drmemtrace]: Appended memref type write (1) size 4 to 0xffffce88d000
[drmemtrace]: Chunk instr count is now 40505
0x0000ffff86090dcc cb010061 sub %x3 %x1 lsl $0x00 -> %x1
[drmemtrace]: Appended encoding entry for 0xfffd8623adcc sz=4 0xcb010061...
[drmemtrace]: Appended instr fetch for original 0xffff86090dcc
[drmemtrace]: Chunk instr count is now 40506
0x0000ffff86090dd0 9400484c bl $0x0000ffff860a2f00 -> %x30
[drmemtrace]: Appended encoding entry for 0xfffd8623add0 sz=4 0x9400484c...
[drmemtrace]: Appended instr fetch for original 0xffff86090dd0
[drmemtrace]: Delaying 2 entries for decode=0xfffd8623add0
[drmemtrace]: Remembered delayed branch decode=0xfffd8623add0 target=0xffff860a2f00
[drmemtrace]: Appending 2 instrs in bb 0xfffd8624cf00 in mod 7 +0x17f00 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff860a2f00 d2801c48 movz $0x00e2 lsl $0x00 -> %x8
[drmemtrace]: Appending delayed branch type=14 pc=0xffff86090dd0 decode=0xfffd8623add0 target=0xffff860a2f00 for thread 0
[drmemtrace]: Appending delayed branch tagalong entry type encoding (47) for thread 0
[drmemtrace]: Chunk instr count is now 40507
[drmemtrace]: Appended encoding entry for 0xfffd8624cf00 sz=4 0xd2801c48...
[drmemtrace]: Appended instr fetch for original 0xffff860a2f00
[drmemtrace]: Chunk instr count is now 40508
0x0000ffff860a2f04 d4000001 svc $0x0000
[drmemtrace]: Appended encoding entry for 0xfffd8624cf04 sz=4 0xd4000001...
[drmemtrace]: Appended instr fetch for original 0xffff860a2f04
[drmemtrace]: Chunk instr count is now 40509
[drmemtrace]: Appended marker type 25 value 0xe2
[drmemtrace]: Chunk instr count is now 40509
[drmemtrace]: Thread 2687566 timestamp 0x002f6825eba0e383
[drmemtrace]: Chunk instr count is now 40509
[drmemtrace]: Appended marker type 3 value 0x1b
[drmemtrace]: Chunk instr count is now 40509
[drmemtrace]: Appending 2 instrs in bb 0xfffd8624cf08 in mod 7 +0x17f08 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
0x0000ffff860a2f08 b13ffc1f adds %x0 $0x0fff lsl $0x00 -> %xzr
[drmemtrace]: Appended encoding entry for 0xfffd8624cf08 sz=4 0xb13ffc1f...
[drmemtrace]: Appended instr fetch for original 0xffff860a2f08
[drmemtrace]: Chunk instr count is now 40510
0x0000ffff860a2f0c 54000042 b.cs $0x0000ffff860a2f14
[drmemtrace]: Appended encoding entry for 0xfffd8624cf0c sz=4 0x54000042...
[drmemtrace]: Appended instr fetch for original 0xffff860a2f0c
[drmemtrace]: Delaying 2 entries for decode=0xfffd8624cf0c
[drmemtrace]: Remembered delayed branch decode=0xfffd8624cf0c target=0xffff860a2f14
[drmemtrace]: Appending 1 instrs in bb 0xfffd8624cf10 in mod 7 +0x17f10 = /usr/lib/aarch64-linux-gnu/ld-2.31.so
I grep'd the file for 200 lines before and 20 lines after each mention.
The full list is on the ci machine in the file named "filtered" in /home
Looking in the log I found the line that matters by searching for the timestamp right after the omitted instruction:
0x0000ffff860a2f04 d4000001 svc $0x0000
[drmemtrace]: Omitting syscall instr without subsequent number marker.
[drmemtrace]: Thread 2687566 timestamp 0x002f6825eba3566d
So there is no number marker and raw2trace thinks it's due to one of the 2 scenarios described in raw2trace_t::should_omit_syscall().
0xe2 is 226 is SYS_mprotect. If its address range includes DR managed memory, DR turns it into a nop, and the tracer's syscall event is not reached: and thus there would be no number marker. That is the only theory I have right now.
If you run (could be plain DR w/o memtrace) with -debug -loglevel 2 is there a log saying turning system call into a nop after Application changing protections of xxx memory... -- and what is xxx?
I ran the test with
${DRUN} -debug -loglevel 2 -- ./hot_swissmap_smoketest
Greping through the logs does show a few SYS_mprotect but nothing similar to what you mention above. The only mention of a nop is in a list generated towards the end of the output once I crank the log level to 4:
recreate_app : pc is in F7037(0x0000fffdacdb62f0)
ilist for recreation:
TAG 0x0000fffdacdb62f0
+0 L3 @0x0000fffdadcdeeb8 f94027e2 ldr +0x48(%sp)[8byte] -> %x2
+4 L3 @0x0000fffdadcdf9e8 2a0003e4 orr %wzr %w0 lsl $0x00 -> %w4
+8 L3 @0x0000fffdadce0700 f9402fe3 ldr +0x58(%sp)[8byte] -> %x3
+12 L3 @0x0000fffdadcdfca0 aa1303e0 orr %xzr %x19 lsl $0x00 -> %x0
+16 L3 @0x0000fffdadcdf390 aa1703e1 orr %xzr %x23 lsl $0x00 -> %x1
+20 L3 @0x0000fffdadcdf308 d2800e68 movz $0x0073 lsl $0x00 -> %x8
+24 L3 @0x0000fffdadcdf418 a9048be3 stp %x3 %x2 -> +0x48(%sp)[16byte]
+28 m4 @0x0000fffdadce0788 14000000 b @0x0000fffdadcdfde8[8byte]
+32 L4 @0x0000fffdadce0060 17cb688b b $0x0000fffdacdb630c
+36 m4 @0x0000fffdadcdfde8 17cb688b <label note=0x0000000000000000>
+36 L3 @0x0000fffdadce04b0 d4000001 svc $0x0000
+40 L4 @0x0000fffdadcdfec8 d503201f nop
+44 L4 @0x0000fffdadce0898 17cb688c b $0x0000fffdacdb6310
END 0x0000fffdacdb62f0
One thing we notice is that you're disabling rseq with GLIBC_TUNABLES=glibc.pthread.rseq=0 -- does it hit a problem without that? We thought #5431 was fixed.