novatek: the HDAL test under load -- H.265 runs out of time, not order; IVE's driver races itself

CLAUDE.md

@@ -413,7 +413,12 @@ compensated for the unsigned alpha. Motion detection is the MDBC
 name). `kdrv_md` waits for frame end with no timeout. The algorithm is
 undocumented, so the background model is a deterministic reduced
 SuBSENSE in buffers only the engine reads. The IVE (`hw/misc/nvt-ive.c`,
-node `ive@f0d70000`) completes a job in its START write. OpenIPC's
+node `ive@f0d70000`) runs a job at START with that job's registers and
+raises its frame end ~1 ms later, one per job. The driver's
+nonblocking trigger releases its lock before it leaves RUN, so on a slow
+host the other channel's trigger can be refused ("illegal in RUN state")
+and the SDK sample then checks an empty buffer: the test reruns it on
+that refusal. OpenIPC's
 `kdrv_ive.ko` cannot load (it needs `kdrv_ive_waitdone_nonblock`), so
 `build-novatek-hdal-samples.sh --kernel` rebuilds it from v1.01.007's
 objects. The

docs/novatek.md

@@ -1492,10 +1492,27 @@ The rest is a guess:
   replaces a pixel with its window's most frequent valid 6-bit value when
   THR_S and THR_H pass.
 
-A job completes as its start is written. The driver clears its flags
-first, and the non-blocking sample polls with a timeout of 0. START
-clears itself, since the driver never does, and bit 31 of 0x68 reads
-idle.
+A job runs as its START is written, with the registers it started with,
+and raises frame end some 1 ms later, as a silicon job would. A second
+job started in that time runs at its own START and gets its own frame
+end, 1 ms after the first: no job is lost to the next one's registers.
+The non-blocking sample's poll with a timeout of 0 retries a job whose
+frame end has not come yet. START clears itself, since the driver never
+does, and bit 31 of 0x68 reads idle.
+
+The non-blocking sample can lose a job to a race in the vendor driver:
+- `kdrv_ive_trigger_nonblock` → `trigger_internal` runs `setMode` and
+  `ive_start` (state machine to RUN) under a semaphore;
+- it releases the semaphore and returns;
+- only then does `kdrv_ive_trigger_nonblock` call `ive_pause` (out of
+  RUN).
+A second channel's thread waiting on the semaphore can run in that gap.
+Its `setMode` is refused ("Operation 2 illegal in RUN state"), and the
+sample, which ignores the refused trigger, checks an empty buffer. On
+silicon `setMode` takes microseconds and the threads rarely meet. Under
+emulation on a loaded host they meet often. The test reruns the sample,
+up to three tries, when it fails after such a refusal, and fails on any
+other error.
 
 With `--kmods` and samples built with `--kernel`, `test-novatek-hdal.sh`
 loads the rebuilt module and checks that it binds. It then runs three

qemu-boot/test-novatek-hdal.sh

@@ -289,20 +289,37 @@ for b in /dev/mmcblk0 /dev/mmcblk1; do
 done
 mkfs.vfat $SDCARD >/dev/null && mount -t vfat $SDCARD /mnt/sd
 cd /tmp/smp
-run() {         # run <sample> [keys]: the keys 4 s apart, then q ($ARGS)
+# run <sample> [keys]: the keys 4 s apart, then q ($ARGS).  With WAIT_FILE
+# and WAIT_BYTES, q waits (up to 40 s more) for the file to grow that big:
+# under load QEMU codes fewer pictures a second than silicon would.
+# push_in errors are counted apart: a sample that feeds a real-time rate
+# with a timeout of 0 drops input frames when the emulation falls behind.
+run() {
     n=$1
     shift
-    ( sleep 6; for k in "$@"; do echo "$k"; sleep 4; done; echo q ) |
-        timeout 60 ./$n $ARGS > /tmp/$n.out 2>&1
+    ( sleep 6
+      i=0
+      while [ -n "$WAIT_FILE" ] && [ $i -lt 40 ] &&
+            [ "$(size $WAIT_FILE)" -lt "$WAIT_BYTES" ]; do
+          sleep 1
+          i=$((i + 1))
+      done
+      for k in "$@"; do echo "$k"; sleep 4; done; echo q ) |
+        timeout 100 ./$n $ARGS > /tmp/$n.out 2>&1
     RC=$?
-    ERRS=$(grep -c -i 'err\|fail' /tmp/$n.out)
+    ERRS=$(grep -i 'err\|fail' /tmp/$n.out | grep -vc 'push_in error')
+    DROPS=$(grep -c 'push_in error' /tmp/$n.out)
     echo "NVT-HDAL-RUN: $n${ARGS:+ $ARGS} rc=$RC errors=$ERRS"
-    grep -i 'err\|fail' /tmp/$n.out | head -3 | sed 's/^/NVT-HDAL-ERR: /'
+    [ "$DROPS" -gt 0 ] && echo "NVT-HDAL-DROPS: $n${ARGS:+ $ARGS} $DROPS"
+    grep -i 'err\|fail' /tmp/$n.out | grep -v 'push_in error' | head -3 |
+        sed 's/^/NVT-HDAL-ERR: /'
 }
 size() {
     [ -f "$1" ] && wc -c < "$1" || echo 0
 }
+WAIT_FILE=/mnt/sd/dump_bs_main.dat WAIT_BYTES=16000
 run hd_video_record
+WAIT_FILE=
 echo "NVT-HDAL-RECORD-BYTES: $(size /mnt/sd/dump_bs_main.dat)"
 echo "NVT-HDAL-REC-B64-BEGIN"
 head -c 6000000 /mnt/sd/dump_bs_main.dat | base64
@@ -432,9 +449,19 @@ if [ -e /dev/nvt_ai_module0 ] && [ -x ./ai_op ]; then
             echo "NVT-IVE-LUT: ok=$(grep -c 'data check ok' /tmp/ive.out)" \
                  "err=$(grep -c 'data check error' /tmp/ive.out)" \
                  "last=$(grep 'data check ok' /tmp/ive.out | tail -1 | sed 's/.*test_width=//')"
-            ( sleep 20; echo q ) | timeout 120 ./alg_ive_lut_sample_nonblocking \
-                > /tmp/ive.out 2>&1
-            echo "NVT-HDAL-RUN: alg_ive_lut_sample_nonblocking rc=$?"
+            # (a refused trigger -- the driver's race between channels,
+            # see docs/novatek.md -- leaves the sample checking an empty
+            # buffer: then, and only then, it runs again, up to 3 tries)
+            for try in 1 2 3; do
+                dmesg -c > /dev/null
+                ( sleep 20; echo q ) | timeout 120 ./alg_ive_lut_sample_nonblocking \
+                    > /tmp/ive.out 2>&1
+                rc=$?
+                grep -q 'data check error' /tmp/ive.out &&
+                    dmesg | grep -q 'illegal in RUN state' || break
+                echo "NVT-IVE-RACE: try $try refused a trigger"
+            done
+            echo "NVT-HDAL-RUN: alg_ive_lut_sample_nonblocking rc=$rc"
             echo "NVT-IVE-NB: t1=$(grep -c 'data check ok.*thread(1)' /tmp/ive.out)" \
                  "t2=$(grep -c 'data check ok.*thread(2)' /tmp/ive.out)" \
                  "err=$(grep -c 'data check error' /tmp/ive.out)"
@@ -632,34 +659,45 @@ PY
         ffmpeg -v error -xerror -f $2 -i "$WORK/enc$1.bin" \
             -f rawvideo -pix_fmt nv12 "$WORK/dec$1.yuv" \
             > "$WORK/dec$1.log" 2>&1 || true
-        # the sample feeds the file's 30 frames round and round: find
-        # where the stream starts in it, then every decoded picture must
-        # be the next frame (PSNR), and the pictures must move
+        # the sample feeds the file's 30 frames round and round: each
+        # decoded picture must be one of them (PSNR), each the next or a
+        # few after the last (the sample drops the frames it cannot push
+        # in when the emulation falls behind), and the pictures must move
         look=$(python3 - "$WORK/initramfs/encin/video_frm_352_288_30_yuv420.dat" \
             "$WORK/dec$1.yuv" <<'PY' 2>/dev/null || true
 import math, sys
 fs = 352 * 288 * 3 // 2
 src = open(sys.argv[1], 'rb').read()
 dec = open(sys.argv[2], 'rb').read()
-ins = [src[i:i + fs] for i in range(0, len(src), fs)]
-outs = [dec[i:i + fs] for i in range(0, len(dec) - fs + 1, fs)][:60]
+ins = [src[i:i + fs][::7] for i in range(0, len(src), fs)]
+outs = [dec[i:i + fs][::7] for i in range(0, len(dec) - fs + 1, fs)][:60]
 def psnr(a, b):
-    se = sum((x - y) ** 2 for x, y in zip(a[::7], b[::7]))
-    return 99.0 if not se else 10 * math.log10(255 ** 2 * len(a[::7]) / se)
+    se = sum((x - y) ** 2 for x, y in zip(a, b))
+    return 99.0 if not se else 10 * math.log10(255 ** 2 * len(a) / se)
 if not outs:
-    print('frames=0 psnr=0 moving=0')
+    print('frames=0 psnr=0 moving=0 order=0 skips=0')
     sys.exit()
-k = max(range(len(ins)), key=lambda i: psnr(outs[0], ins[i]))
-worst = min(psnr(o, ins[(k + i) % len(ins)]) for i, o in enumerate(outs))
+best = [max(((psnr(o, f), j) for j, f in enumerate(ins))) for o in outs]
+worst = min(p for p, _ in best)
+steps = [(b[1] - a[1]) % len(ins) for a, b in zip(best, best[1:])]
 moving = sum(a != b for a, b in zip(outs, outs[1:]))
-print('frames=%d psnr=%.1f moving=%d' % (len(dec) // fs, worst, moving))
+print('frames=%d psnr=%.1f moving=%d order=%d skips=%d'
+      % (len(dec) // fs, worst, moving, all(1 <= t <= 4 for t in steps),
+         sum(t > 1 for t in steps)))
 PY
 )
         frames=$(echo "$look" | sed -n 's/.*frames=\([0-9]*\).*/\1/p')
         psnr=$(echo "$look" | sed -n 's/.*psnr=\([0-9]*\).*/\1/p')
         moving=$(echo "$look" | sed -n 's/.*moving=\([0-9]*\).*/\1/p')
+        order=$(echo "$look" | sed -n 's/.*order=\([0-9]*\).*/\1/p')
+        drops=$(grep -a "^NVT-HDAL-DROPS: hd_video_encode_only $1 " \
+                "$WORK/console.log" | tr -d '\r' | awk '{print $NF}' || true)
+        look="$look drops=${drops:-0}"
+        # dropped input is the emulation's speed, but at most a quarter
         if [ -s "$WORK/dec$1.log" ] || [ "${frames:-0}" -lt 5 ] ||
-                [ "${psnr:-0}" -lt 30 ] || [ "${moving:-0}" -lt 4 ]; then
+                [ "${psnr:-0}" -lt 30 ] || [ "${moving:-0}" -lt 4 ] ||
+                [ "${order:-0}" != 1 ] ||
+                [ $(( ${drops:-0} * 4 )) -gt "${frames:-0}" ]; then
             bad "$3 from hd_video_encode_only decodes to the input, in order ($look; $(head -c 200 "$WORK/dec$1.log"))"
         else
             pass "$3 from hd_video_encode_only decodes to the input, in order ($look)"

qemu/hw/misc/nvt-media.c

@@ -80,6 +80,7 @@ struct NvtMediaState {
      */
     NvtAiWork *ai_work;
     uint32_t ai_pending;
+    uint32_t ive_done;          /* IVE: jobs run, frame ends still to raise */
     uint32_t *ai_regs;
     uint32_t ai_res;
 };
@@ -341,9 +342,10 @@ static const NvtIppParams ipp_md = {
  * resets, bit 1 runs a job, bit 28 fires a list (job end bit 10, list
  * end bit 8, a broken list bit 9); frame end is status bit 0, which every
  * sample waits for with no timeout.  kdrv_ive sets bit 1 and never clears
- * it, so a job clears it.  The work is nvt-ive.c's, done as the start is
- * written: the driver clears its flags before it starts, and the
- * non-blocking sample polls with a timeout of 0.  Bit 31 of 0x68 reads
+ * it, so a job clears it.  The work is nvt-ive.c's, done as START is
+ * written, with the registers the job started with; its frame end comes
+ * some 1 ms later, as a silicon job's would, and a second job started
+ * meanwhile gets its own, 1 ms after the first.  Bit 31 of 0x68 reads
  * idle.
  */
 static const NvtIppParams ipp_ive = {
@@ -389,18 +391,20 @@ static uint64_t ipp_write(NvtMediaState *s, hwaddr off, uint64_t val)
 
         return (val & ~ro) | (*reg(s, off) & ro);
     }
-    if (off == IPP_CTRL && p == &ipp_ive) {
-        if (val & 1) {
-            /* reset: a running list and the status go */
-            timer_del(s->timer);
-            *reg(s, p->ints) = 0;
-            return val & ~(1u | p->trig | IPP_LL_FIRE);
-        }
-        if (val & p->trig) {
-            nvt_ive_run(s->regs);
-            *reg(s, p->ints) |= p->trig_end;
-            val &= ~p->trig;
+    if (off == IPP_CTRL && p == &ipp_ive && (val & 1)) {
+        /* reset: the jobs' frame ends still to come and the status go */
+        timer_del(s->timer);
+        s->ive_done = 0;
+        *reg(s, p->ints) = 0;
+        return val & ~(1u | p->trig | IPP_LL_FIRE);
+    }
+    if (off == IPP_CTRL && p == &ipp_ive && (val & p->trig)) {
+        nvt_ive_run(s->regs);
+        if (!s->ive_done++) {
+            timer_mod(s->timer, qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) +
+                      IPP_JOB_NS);
         }
+        return val & ~p->trig;
     }
     if (p == &ipp_ive && (off == 0x054 || off == 0x058)) {
         return *reg(s, off);                /* the IRV counters */
@@ -737,6 +741,17 @@ static void ipp_job_done(NvtMediaState *s)
     bool ai = ai_engine_run(s);
     IppLlResult res;
 
+    if (p == &ipp_ive && s->ive_done) {
+        /* a job already run: its frame end, then the next one's */
+        *reg(s, p->ints) |= p->trig_end;
+        ipp_update_irq(s);
+        if (--s->ive_done) {
+            timer_mod(s->timer, qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) +
+                      IPP_JOB_NS);
+        }
+        return;
+    }
+
     if (ai && s->ai_work) {
         /* started again while a job is on the worker: once it is back */
         timer_mod(s->timer, qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) +
@@ -1103,6 +1118,7 @@ static void nvt_media_reset(DeviceState *dev)
     memset(s->regs, 0, s->size);
     ai_job_detach(s);           /* a job on the worker comes back void */
     s->ai_pending = 0;
+    s->ive_done = 0;
     s->frames = 0;
     s->jpg_lut = 0;
     memset(s->jpg_q, 0, sizeof(s->jpg_q));
@@ -1180,7 +1196,7 @@ static int nvt_media_post_load(void *opaque, int version_id)
 
 static const VMStateDescription vmstate_nvt_media = {
     .name = TYPE_NVT_MEDIA,
-    .version_id = 2,
+    .version_id = 3,
     .minimum_version_id = 1,
     .post_load = nvt_media_post_load,
     .fields = (const VMStateField[]) {
@@ -1194,6 +1210,7 @@ static const VMStateDescription vmstate_nvt_media = {
         VMSTATE_UINT32_V(ai_pending, NvtMediaState, 2),
         VMSTATE_UINT32_V(ai_res, NvtMediaState, 2),
         VMSTATE_VBUFFER_UINT32(ai_regs, NvtMediaState, 2, NULL, size),
+        VMSTATE_UINT32_V(ive_done, NvtMediaState, 3),
         VMSTATE_END_OF_LIST()
     }
 };

qemu/tests/test-novatek.py

@@ -2259,6 +2259,7 @@ def ive_job(qt, w, h, func, img, out_lofs, regs=None):
     qt.writel(IVE + 0x008, 0x701)
     qt.writel(IVE + 0x004, 0x301)
     qt.writel(IVE + 0x000, qt.readl(IVE + 0x000) | 2)
+    ai_settle(qt, IVE + 0x008, 1)
     return qt.read(AI_OUT, out_lofs * h)
 
 
@@ -2280,7 +2281,7 @@ def test_ive(qt):
     check('IVE: idle (0x68 bit 31)', qt.readl(IVE + 0x068) >> 31, 1)
     # the threshold LUT, 1 bit: over Th0, LSB first
     out = ive_job(qt, w, h, 1 << 13, img, 4, {0x03C: 100})
-    check('IVE LUT 1-bit: over Th0, done in the start write',
+    check('IVE LUT 1-bit: over Th0, then frame end, START cleared',
           (ive_bits(out, w, h, 4, 1), qt.readl(IVE + 0x008) & 1,
            qt.readl(IVE + 0x000) & 2, gic_pending(qt, 53)),
           ([int(v > 100) for v in img], 1, 0, True))
@@ -2343,6 +2344,31 @@ def test_ive(qt):
     check('IVE IRV: the invalid pixel takes its window\'s value',
           (ive_bits(out, w, h, 16, 8)[4 * w + 6], qt.readl(IVE + 0x054)),
           (20, w * h))
+    # two jobs started within a job's time (the non-blocking sample's two
+    # channels): each runs with its own registers and raises its own
+    # frame end, 1 ms after the one before
+    qt.write(AI_IN, b''.join(bytes(img[y * w:(y + 1) * w]) +
+                             bytes(((w + 3) & ~3) - w) for y in range(h)))
+    qt.write(AI_OUT, bytes(8 * h))
+    qt.writel(IVE + 0x008, 0x701)
+    for off, val in {0x010: 1 << 13, 0x014: AI_IN, 0x018: (w + 3) & ~3,
+                     0x020: 4, 0x024: w | h << 16}.items():
+        qt.writel(IVE + off, val)
+    for out, th in ((AI_OUT, 100), (AI_OUT + 4 * h, 200)):
+        qt.writel(IVE + 0x01C, out)
+        qt.writel(IVE + 0x03C, th)
+        qt.writel(IVE + 0x000, qt.readl(IVE + 0x000) | 2)
+    first = qt.readl(IVE + 0x008) & 1
+    ai_settle(qt, IVE + 0x008, 1)
+    qt.writel(IVE + 0x008, 1)
+    ai_settle(qt, IVE + 0x008, 1)
+    second = qt.readl(IVE + 0x008) & 1
+    qt.writel(IVE + 0x008, 1)
+    outs = qt.read(AI_OUT, 8 * h)
+    check('IVE: two jobs started at once each run and each end',
+          (first, second, ive_bits(outs, w, h, 4, 1),
+           ive_bits(outs[4 * h:], w, h, 4, 1)),
+          (0, 1, [int(v > 100) for v in img], [int(v > 200) for v in img]))
     # a reset clears the status, keeps the enables
     qt.writel(IVE + 0x000, 1)
     qt.writel(IVE + 0x000, 0)