LekKit / RVVM

The RISC-V Virtual Machine
GNU General Public License v3.0
871 stars 61 forks source link

i2c-hid: Linux guest hangs on input spam at boot stage #126

Closed LekKit closed 2 months ago

LekKit commented 6 months ago

Converted issue; See https://github.com/LekKit/RVVM/issues/126#issuecomment-1981278618

Older issue ### Steps to reproduce - Have a very slow guest (`rvvm_set_opt(machine, RVVM_OPT_MAX_CPU_CENT, 1)` or immediately call `hid_keyboard_release()`) - Some key presses will be lost when typing - Same possibly applies to hid_mouse ### Investigation - Press/release API calls just mark/unmark a bit in pressed keys bitmask, then mark that input is available on HID device - Guest reads input report, which enumerates pressed keys - if release() happens before this, no pressed keys are reported ### Suggested fix My initial idea is to have two key bitmasks: `keys_report` and `keys_pressed`. - On `hid_keyboard_press()`, a bit is set in both bitmasks; - On `hid_keyboard_release()`, a bit is cleared only in `keys_pressed` bitmask. - When guest is reading input report, a key should be reported as pressed if it's bit is set in **either** bitmasks. - Then, if the bit is actually cleared in `keys_pressed`, then that means we now should replay a key release event, so `input_avail()` should be called. Finally, the bit in `keys_report` is cleared. The problem is, `input_avail()` locking causes recursive deadlock inside `i2c-hid` when calling from `read_report` handler. This needs further investigation - I see there is some queueing mechanism available inside `i2c-hid`, so maybe we can actually queue input reports instead, but haven't read into that code much yet. @X547 perhaps you can point me in the right direction? I am wondering if HID reports should be just queued as packets and not call back into the device `read_report` handler, this would also allow copy-paste into `hid_keyboard` beyond just fixing this issue. In the mean time I'll be polishing network code for a new stable release, and will be back to this issue soon
LekKit commented 6 months ago

So according to ic2-hid implementation if input_available() is called twice, read_report() should be called twice by the I2C-HID controller by holding an interrupt until the report queue is drained - which should have allowed my hid_keyboard fix to work, but it doesn't exactly work on Linux guest.

image

If we immediately call input_available() twice, sometimes second read_report() call is made with huge (3-4 seconds) delay, and in between those calls the guest believes that the button is still pressed and performs repeated key input, etc.

What's even more intriguing is that interrupt line of I2C-HID device is asserted all this time and not lowered until guest reads the second report. It's not like the guest is overrun with interrupts either - numbers in /proc/interrupts are around 10-100 mark, not gazzilions. So it must have ignore the raised interrupt of I2C-HID which signals there are more reports to be read, and only comes back after a huge delay.

I tried to test same VM with Haiku guest, no problems at all. Guest reads both reports immediately and registers a key click.

I went further and put repeated plic_send_irq() each 10ms into I2C OC controller to make sure that device doesn't have any interrupts that guest might wait for (There was a bug a while ago, because it seems Linux expects more interrupt cases from this device than there are documented, like an interrupt on transaction stop). It fixed the issue! But ehm, I am not sure I2C controller is at fault... Any operation it could have done already signals an interrupt, I tried to send IRQ on any CRSR write except when it actually clears interrupts and nothing changed.

So here are possible causes of this particular bug

I will go have a look at how PLIC handles level-triggered IRQs as I have some second thoughts here.

@X547 can you give me any available pieces of documentation about I2C HID you have used / have access to? Seems problematic for me to find. It might be a good idea to have doc links around somewhere.

LekKit commented 6 months ago

It is indeed a PLIC bug, plic_scan_irqs() should be called when setting interrupt priority non-zero (Tho we also need to figure out what CTX this IRQ should be forwarded to).

Will include a fix soon.

LekKit commented 6 months ago

I also want to redesign HID Device API somewhat. Instead of using report id queue, and relying on "read_report()` being called as many times as needed, why not queue complete report packets instead?

The old input_available() function will only raise an interrupt, and report would be read once - this will be useful for mouse move events as many move events may be merged into a single IRQ and a single read_report() if guest is slow. The read_report() function will also return a bool indicating there are more reports to read (for future designs).

There will be another api, queue_report() which will be called from input device side and handled by HID controller. It will queue entire report packet inside I2C HID (using a ring buffer), and allow bursts of input events without any complications inside actual input device implementations.

My fix to PLIC and initial fix for hid_keyboard will be merged beforehand.

X547 commented 6 months ago

Queuing events may cause other problems like shock wave effect when events are enqueued faster than processed.

X547 commented 6 months ago

@X547 can you give me any available pieces of documentation about I2C HID you have used / have access to? Seems problematic for me to find. It might be a good idea to have doc links around somewhere.

https://download.microsoft.com/download/7/d/d/7dd44bb7-2a7a-4505-ac1c-7227d3d96d5b/hid-over-i2c-protocol-spec-v1-0.docx

LekKit commented 6 months ago

Queuing events may cause other problems like shock wave effect when events are enqueued faster than processed.

Ring buffer has limited size so they will be dropped in such case, current implementation in the repo technically works like a single buffered event inside input device state. With a ring buffer we can queue N events, but no more. It is beneficial for keyboard-like devices where loss of events upon burst will affect usability.

For devices which spam a lot of events (mouse movement) the older read_report() API will be kept & optimized, so that multiple input events may coalesce into a single report with slower guest.

I think that would be a good combination however I want to fix PLIC first and upload initial hid_keyboard fix which doesn't change the design, only then experiment with anything new

https://download.microsoft.com/download/7/d/d/7dd44bb7-2a7a-4505-ac1c-7227d3d96d5b/hid-over-i2c-protocol-spec-v1-0.docx

Thanks!

LekKit commented 6 months ago

There is another bug where Linux guest will sometimes hang if input_available is called very early in the boot process (For example spamming input on a booting guest). It seems that I2C-HID interrupt is raised and never lowered. Perhaps the if (!i2c_hid->is_reset) check isn't enough to prevent interrupt being sent too early?

X547 commented 6 months ago

Maybe Linux performs some i2c read/write operations before properly initializing interrupt handler? Is it possible to add logging of i2c_hid_stop, i2c_hid_reset calls?

LekKit commented 6 months ago

Maybe Linux performs some i2c read/write operations before properly initializing interrupt handler? Is it possible to add logging of i2c_hid_stop, i2c_hid_reset calls?

I have logged raise/lower events of IRQ 8 (assigned to I2C-HID) from PLIC when the state actually changes, and i2c_hid_start/stop events. This is combined with guest log so you can see where it's at.

The guest is not completely dead as the framebuffer tty cursor is blinking. However it is overflown with I2C-HID interrupts (It always claims them, but doesn't seem to perform any I2C HID activity after the last line in the log).

A long log ``` [ 0.0] WARN: Raise irq 8 OpenSBI v1.2 ____ _____ ____ _____ / __ \ / ____| _ \_ _| | | | |_ __ ___ _ __ | (___ | |_) || | | | | | '_ \ / _ \ '_ \ \___ \| _ < | | | |__| | |_) | __/ | | |____) | |_) || |_ \____/| .__/ \___|_| |_|_____/|____/_____| | | |_| Platform Name : RVVM v0.6-unknown Platform Features : medeleg Platform HART Count : 1 Platform IPI Device : aclint-mswi Platform Timer Device : aclint-mtimer @ 10000000Hz Platform Console Device : uart8250 Platform HSM Device : --- Platform PMU Device : --- Platform Reboot Device : sifive_test Platform Shutdown Device : sifive_test Firmware Base : 0x80000000 Firmware Size : 212 KB Runtime SBI Version : 1.0 Domain0 Name : root Domain0 Boot HART : 0 Domain0 HARTs : 0* Domain0 Region00 : 0x0000000002000000-0x000000000200ffff (I) Domain0 Region01 : 0x0000000080000000-0x000000008003ffff () Domain0 Region02 : 0x0000000000000000-0xffffffffffffffff (R,W,X) Domain0 Next Address : 0x0000000080200000 Domain0 Next Arg1 : 0x0000000080100000 Domain0 Next Mode : S-mode Domain0 SysReset : yes Boot HART ID : 0 Boot HART Domain : root Boot HART Priv Version : v1.11 Boot HART Base ISA : rv64imafdc Boot HART ISA Extensions : time Boot HART PMP Count : 0 Boot HART PMP Granularity : 0 Boot HART PMP Address Bits: 0 Boot HART MHPM Count : 0 Boot HART MIDELEG : 0x0000000000000222 Boot HART MEDELEG : 0x000000000000b109 [ 0.000000] Linux version 6.4.1-rvvm (lekkit@LekKit-PC) (riscv64-linux-gnu-gcc (GCC) 12.2.0, GNU ld (GNU Binutils) 2.39) #5 SMP PREEMPT Sat Jul 1 17:44:20 EEST 2023 [ 0.000000] random: crng init done [ 0.000000] Machine model: RVVM v0.6-unknown [ 0.000000] efi: UEFI not found. [ 0.000000] OF: reserved mem: 0x0000000080000000..0x000000008003ffff (256 KiB) nomap non-reusable mmode_resv0@80000000 [ 0.000000] Zone ranges: [ 0.000000] DMA32 [mem 0x0000000080000000-0x000000008fffffff] [ 0.000000] Normal empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000080000000-0x000000008003ffff] [ 0.000000] node 0: [mem 0x0000000080040000-0x000000008fffffff] [ 0.000000] Initmem setup node 0 [mem 0x0000000080000000-0x000000008fffffff] [ 0.000000] SBI specification v1.0 detected [ 0.000000] SBI implementation ID=0x1 Version=0x10002 [ 0.000000] SBI TIME extension detected [ 0.000000] SBI IPI extension detected [ 0.000000] SBI RFENCE extension detected [ 0.000000] SBI SRST extension detected [ 0.000000] SBI HSM extension detected [ 0.000000] riscv: base ISA extensions acdfim [ 0.000000] riscv: ELF capabilities acdfim [ 0.000000] percpu: Embedded 15 pages/cpu s29864 r0 d31576 u61440 [ 0.000000] Kernel command line: console=ttyS console=tty0 root=/dev/nvme0n1 rootflags=discard rw [ 0.000000] Dentry cache hash table entries: 32768 (order: 6, 262144 bytes, linear) [ 0.000000] Inode-cache hash table entries: 16384 (order: 5, 131072 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 64640 [ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off [ 0.000000] Memory: 251968K/262144K available (3803K kernel code, 496K rwdata, 1045K rodata, 254K init, 224K bss, 10176K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-1, MinObjects=0, CPUs=1, Nodes=1 [ 0.000000] rcu: Preemptible hierarchical RCU implementation. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=32 to nr_cpu_ids=1. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1 [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0 [ 0.000000] riscv-intc: 64 local interrupts mapped [ 0.000000] plic: plic@c000000: mapped 63 interrupts with 1 handlers for 2 contexts. [ 0.000000] riscv: providing IPIs using SBI IPI extension [ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention. [ 0.000000] riscv-timer: riscv_timer_init_dt: Registering clocksource cpuid [0] hartid [0] [ 0.000000] clocksource: riscv_clocksource: mask: 0xffffffffffffffff max_cycles: 0x24e6a1710, max_idle_ns: 440795202120 ns [ 0.000049] sched_clock: 64 bits at 10MHz, resolution 100ns, wraps every 4398046511100ns [ 0.006796] Console: colour dummy device 80x25 [ 0.007032] printk: console [tty0] enabled [ 0.014410] Calibrating delay loop (skipped), value calculated using timer frequency.. 20.00 BogoMIPS (lpj=10000) [ 0.014686] pid_max: default: 32768 minimum: 301 [ 0.018027] Mount-cache hash table entries: 512 (order: 0, 4096 bytes, linear) [ 0.018159] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes, linear) [ 0.045876] riscv: ELF compat mode supported [ 0.046661] ASID allocator disabled (0 bits) [ 0.047993] rcu: Hierarchical SRCU implementation. [ 0.048090] rcu: Max phase no-delay instances is 400. [ 0.051111] EFI services will not be available. [ 0.051877] smp: Bringing up secondary CPUs ... [ 0.052009] smp: Brought up 1 node, 1 CPU [ 0.059702] devtmpfs: initialized [ 0.071903] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.072328] futex hash table entries: 256 (order: 2, 16384 bytes, linear) [ 0.075307] NET: Registered PF_NETLINK/PF_ROUTE protocol family [ 0.080225] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations [ 0.080776] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.102909] Advanced Linux Sound Architecture Driver Initialized. [ 0.114686] clocksource: Switched to clocksource riscv_clocksource [ 0.169570] NET: Registered PF_INET protocol family [ 0.171768] IP idents hash table entries: 4096 (order: 3, 32768 bytes, linear) [ 0.178863] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.179159] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) [ 0.179442] TCP established hash table entries: 2048 (order: 2, 16384 bytes, linear) [ 0.179774] TCP bind hash table entries: 2048 (order: 4, 65536 bytes, linear) [ 0.180556] TCP: Hash tables configured (established 2048 bind 2048) [ 0.181744] UDP hash table entries: 256 (order: 1, 8192 bytes, linear) [ 0.182045] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear) [ 0.183008] NET: Registered PF_UNIX/PF_LOCAL protocol family [ 0.190114] workingset: timestamp_bits=62 max_order=16 bucket_order=0 [ 0.199147] pci-host-generic 30000000.pci: host bridge /soc/pci@30000000 ranges: [ 0.199963] pci-host-generic 30000000.pci: IO 0x0003000000..0x000300ffff -> 0x0000000000 [ 0.200387] pci-host-generic 30000000.pci: MEM 0x0040000000..0x007fffffff -> 0x0040000000 [ 0.201339] pci-host-generic 30000000.pci: ECAM at [mem 0x30000000-0x3fffffff] for [bus 00-ff] [ 0.202439] pci-host-generic 30000000.pci: PCI host bridge to bus 0000:00 [ 0.202660] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.202810] pci_bus 0000:00: root bus resource [io 0x0000-0xffff] [ 0.202910] pci_bus 0000:00: root bus resource [mem 0x40000000-0x7fffffff] [ 0.203565] pci 0000:00:00.0: [f15e:0000] type 00 class 0x060000 [ 0.205309] pci 0000:00:01.0: [10ec:8169] type 00 class 0x020000 [ 0.205531] pci 0000:00:01.0: reg 0x14: [mem 0x40000000-0x400000ff] [ 0.206161] pci 0000:00:02.0: [144d:a809] type 00 class 0x010802 [ 0.206295] pci 0000:00:02.0: reg 0x10: [mem 0x40004000-0x40007fff] [ 0.207905] pci 0000:00:02.0: BAR 0: assigned [mem 0x40000000-0x40003fff] [ 0.208162] pci 0000:00:01.0: BAR 1: assigned [mem 0x40004000-0x400040ff] [ 0.210000] simple-framebuffer 28000000.framebuffer: framebuffer at 0x28000000, 0x12c000 bytes [ 0.210142] simple-framebuffer 28000000.framebuffer: format=a8r8g8b8, mode=640x480x32, linelength=2560 [ 0.220111] Console: switching to colour frame buffer device 80x30 [ 0.227536] simple-framebuffer 28000000.framebuffer: fb0: simplefb registered! [ 0.444664] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled [ 0.460942] printk: console [ttyS0] disabled [ 0.467348] 10000000.uart: ttyS0 at MMIO 0x10000000 (irq = 12, base_baud = 2500000) is a 16550A [ 0.475109] printk: console [ttyS0] enabled [ 0.508451] loop: module loaded [ 0.513532] zram: Added device: zram0 [ 0.524325] r8169 0000:00:01.0: Mem-Wr-Inval unavailable [ 0.533951] r8169 0000:00:01.0 eth0: RTL8169s, 72:05:5c:60:62:cf, XID 008, IRQ 13 [ 0.538816] r8169 0000:00:01.0 eth0: jumbo features [frames: 7146 bytes, tx checksumming: ok] [ 0.548015] nvme nvme0: pci function 0000:00:02.0 [ 0.583429] mousedev: PS/2 mouse device common for all mice [ 0.588604] goldfish_rtc 101000.rtc: registered as rtc0 [ 0.592093] goldfish_rtc 101000.rtc: setting system clock to 2024-03-06T19:13:33 UTC (1709752413) [ 0.607203] nvme nvme0: 1/0/0 default/read/poll queues [ 0.637603] i2c_dev: i2c /dev entries driver [ 0.91077] WARN: i2c_hid_start [ 0.91090] WARN: i2c_hid_stop [ 0.91112] WARN: i2c_hid_start [ 0.91119] WARN: i2c_hid_start [ 0.91143] WARN: i2c_hid_stop [ 0.91358] WARN: i2c_hid_start [ 0.91366] WARN: i2c_hid_stop [ 0.91372] WARN: i2c_hid_start [ 0.91377] WARN: i2c_hid_start [ 0.91395] WARN: i2c_hid_stop [ 0.92355] WARN: i2c_hid_start [ 0.92371] WARN: i2c_hid_stop [ 0.92608] WARN: i2c_hid_start [ 0.92624] WARN: i2c_hid_stop [ 0.92651] WARN: i2c_hid_start [ 0.92663] WARN: i2c_hid_start [ 0.92708] WARN: i2c_hid_stop [ 0.92804] WARN: i2c_hid_start [ 0.92817] WARN: i2c_hid_stop [ 0.92886] WARN: i2c_hid_start [ 0.92893] WARN: i2c_hid_stop [ 0.93015] WARN: i2c_hid_start [ 0.93028] WARN: i2c_hid_stop [ 0.93103] WARN: i2c_hid_start [ 0.93116] WARN: i2c_hid_stop [ 0.93166] WARN: i2c_hid_start [ 0.93179] WARN: i2c_hid_stop [ 0.93206] WARN: i2c_hid_start [ 0.93216] WARN: i2c_hid_stop [ 0.668437] NET: Registered PF_INET6 protocol family [ 0.93258] WARN: i2c_hid_start [ 0.93271] WARN: i2c_hid_stop [ 0.93365] WARN: i2c_hid_start [ 0.93379] WARN: i2c_hid_stop [ 0.93399] WARN: i2c_hid_start [ 0.93410] WARN: i2c_hid_stop [ 0.93427] WARN: i2c_hid_start [ 0.93441] WARN: i2c_hid_stop [ 0.93464] WARN: i2c_hid_start [ 0.93475] WARN: i2c_hid_stop [ 0.93519] WARN: i2c_hid_start [ 0.93540] WARN: i2c_hid_stop [ 0.93576] WARN: i2c_hid_start [ 0.93588] WARN: i2c_hid_stop [ 0.93610] WARN: i2c_hid_start [ 0.93622] WARN: i2c_hid_stop [ 0.93641] WARN: i2c_hid_start [ 0.93651] WARN: i2c_hid_stop [ 0.93667] WARN: i2c_hid_start [ 0.93679] WARN: i2c_hid_stop [ 0.93705] WARN: i2c_hid_start [ 0.93718] WARN: i2c_hid_stop [ 0.93743] WARN: i2c_hid_start [ 0.93756] WARN: i2c_hid_stop [ 0.93775] WARN: i2c_hid_start [ 0.93789] WARN: i2c_hid_stop [ 0.93811] WARN: i2c_hid_start [ 0.93825] WARN: i2c_hid_stop [ 0.93895] WARN: i2c_hid_start [ 0.93911] WARN: i2c_hid_stop [ 0.93941] WARN: i2c_hid_start [ 0.93957] WARN: i2c_hid_stop [ 0.93981] WARN: i2c_hid_start [ 0.93996] WARN: i2c_hid_stop [ 0.94019] WARN: i2c_hid_start [ 0.94045] WARN: i2c_hid_stop [ 0.94165] WARN: i2c_hid_start [ 0.94177] WARN: i2c_hid_stop [ 0.94200] WARN: i2c_hid_start [ 0.94213] WARN: i2c_hid_stop [ 0.94231] WARN: i2c_hid_start [ 0.94239] WARN: i2c_hid_stop [ 0.94256] WARN: i2c_hid_start [ 0.94264] WARN: i2c_hid_stop [ 0.94279] WARN: i2c_hid_start [ 0.94355] WARN: i2c_hid_stop [ 0.94408] WARN: i2c_hid_start [ 0.94418] WARN: i2c_hid_stop [ 0.94446] WARN: i2c_hid_start [ 0.94456] WARN: i2c_hid_stop [ 0.94504] WARN: i2c_hid_start [ 0.94515] WARN: i2c_hid_stop [ 0.94532] WARN: i2c_hid_start [ 0.94543] WARN: i2c_hid_stop [ 0.94559] WARN: i2c_hid_start [ 0.94569] WARN: i2c_hid_stop [ 0.94584] WARN: i2c_hid_start [ 0.94595] WARN: i2c_hid_stop [ 0.94609] WARN: i2c_hid_start [ 0.94618] WARN: i2c_hid_stop [ 0.94632] WARN: i2c_hid_start [ 0.94640] WARN: i2c_hid_stop [ 0.94656] WARN: i2c_hid_start [ 0.94665] WARN: i2c_hid_stop [ 0.94678] WARN: i2c_hid_start [ 0.94687] WARN: i2c_hid_stop [ 0.94699] WARN: i2c_hid_start [ 0.94709] WARN: i2c_hid_stop [ 0.94721] WARN: i2c_hid_start [ 0.94731] WARN: i2c_hid_stop [ 0.94743] WARN: i2c_hid_start [ 0.94753] WARN: i2c_hid_stop [ 0.94769] WARN: i2c_hid_start [ 0.94782] WARN: i2c_hid_stop [ 0.94807] WARN: i2c_hid_start [ 0.94821] WARN: i2c_hid_stop [ 0.94844] WARN: i2c_hid_start [ 0.94856] WARN: i2c_hid_stop [ 0.94876] WARN: i2c_hid_start [ 0.94889] WARN: i2c_hid_stop [ 0.94909] WARN: i2c_hid_start [ 0.94921] WARN: i2c_hid_stop [ 0.94938] WARN: i2c_hid_start [ 0.94956] WARN: i2c_hid_stop [ 0.94983] WARN: i2c_hid_start [ 0.94997] WARN: i2c_hid_stop [ 0.95015] WARN: i2c_hid_start [ 0.95027] WARN: i2c_hid_stop [ 0.95048] WARN: i2c_hid_start [ 0.95062] WARN: i2c_hid_stop [ 0.95083] WARN: i2c_hid_start [ 0.95111] WARN: i2c_hid_stop [ 0.95148] WARN: i2c_hid_start [ 0.95167] WARN: i2c_hid_stop [ 0.95190] WARN: i2c_hid_start [ 0.95203] WARN: i2c_hid_stop [ 0.95220] WARN: i2c_hid_start [ 0.95232] WARN: i2c_hid_stop [ 0.95249] WARN: i2c_hid_start [ 0.95262] WARN: i2c_hid_stop [ 0.95278] WARN: i2c_hid_start [ 0.95290] WARN: i2c_hid_stop [ 0.95308] WARN: i2c_hid_start [ 0.95321] WARN: i2c_hid_stop [ 0.95339] WARN: i2c_hid_start [ 0.95352] WARN: i2c_hid_stop [ 0.95371] WARN: i2c_hid_start [ 0.95385] WARN: i2c_hid_stop [ 0.95410] WARN: i2c_hid_start [ 0.95422] WARN: i2c_hid_stop [ 0.95438] WARN: i2c_hid_start [ 0.95450] WARN: i2c_hid_stop [ 0.95465] WARN: i2c_hid_start [ 0.95477] WARN: i2c_hid_stop [ 0.95509] WARN: i2c_hid_start [ 0.95520] WARN: i2c_hid_stop [ 0.95564] WARN: i2c_hid_start [ 0.95574] WARN: i2c_hid_stop [ 0.95589] WARN: i2c_hid_start [ 0.95598] WARN: i2c_hid_stop [ 0.95611] WARN: i2c_hid_start [ 0.95620] WARN: i2c_hid_stop [ 0.95634] WARN: i2c_hid_start [ 0.95640] WARN: i2c_hid_stop [ 0.95652] WARN: i2c_hid_start [ 0.95661] WARN: i2c_hid_stop [ 0.95673] WARN: i2c_hid_start [ 0.95683] WARN: i2c_hid_stop [ 0.95697] WARN: i2c_hid_start [ 0.95707] WARN: i2c_hid_stop [ 0.95718] WARN: i2c_hid_start [ 0.95728] WARN: i2c_hid_stop [ 0.95741] WARN: i2c_hid_start [ 0.95750] WARN: i2c_hid_stop [ 0.95762] WARN: i2c_hid_start [ 0.95772] WARN: i2c_hid_stop [ 0.95784] WARN: i2c_hid_start [ 0.95793] WARN: i2c_hid_stop [ 0.95805] WARN: i2c_hid_start [ 0.95814] WARN: i2c_hid_stop [ 0.95826] WARN: i2c_hid_start [ 0.95832] WARN: i2c_hid_stop [ 0.95842] WARN: i2c_hid_start [ 0.95852] WARN: i2c_hid_stop [ 0.95863] WARN: i2c_hid_start [ 0.95873] WARN: i2c_hid_stop [ 0.95884] WARN: i2c_hid_start [ 0.95893] WARN: i2c_hid_stop [ 0.95905] WARN: i2c_hid_start [ 0.95914] WARN: i2c_hid_stop [ 0.95926] WARN: i2c_hid_start [ 0.95936] WARN: i2c_hid_stop [ 0.95947] WARN: i2c_hid_start [ 0.95957] WARN: i2c_hid_stop [ 0.95968] WARN: i2c_hid_start [ 0.95977] WARN: i2c_hid_stop [ 0.95989] WARN: i2c_hid_start [ 0.95998] WARN: i2c_hid_stop [ 0.96010] WARN: i2c_hid_start [ 0.96019] WARN: i2c_hid_stop [ 0.96032] WARN: i2c_hid_start [ 0.96041] WARN: i2c_hid_stop [ 0.96053] WARN: i2c_hid_start [ 0.96062] WARN: i2c_hid_stop [ 0.96073] WARN: i2c_hid_start [ 0.96083] WARN: i2c_hid_stop [ 0.96094] WARN: i2c_hid_start [ 0.96103] WARN: i2c_hid_stop [ 0.96115] WARN: i2c_hid_start [ 0.96125] WARN: i2c_hid_stop [ 0.96136] WARN: i2c_hid_start [ 0.96142] WARN: i2c_hid_stop [ 0.96153] WARN: i2c_hid_start [ 0.96164] WARN: i2c_hid_stop [ 0.96175] WARN: i2c_hid_start [ 0.96184] WARN: i2c_hid_stop [ 0.96195] WARN: i2c_hid_start [ 0.96204] WARN: i2c_hid_stop [ 0.96215] WARN: i2c_hid_start [ 0.96224] WARN: i2c_hid_stop [ 0.96239] WARN: i2c_hid_start [ 0.96250] WARN: i2c_hid_stop [ 0.96262] WARN: i2c_hid_start [ 0.96271] WARN: i2c_hid_stop [ 0.96282] WARN: i2c_hid_start [ 0.96291] WARN: i2c_hid_stop [ 0.96302] WARN: i2c_hid_start [ 0.96311] WARN: i2c_hid_stop [ 0.96324] WARN: i2c_hid_start [ 0.96337] WARN: i2c_hid_stop [ 0.96350] WARN: i2c_hid_start [ 0.96359] WARN: i2c_hid_stop [ 0.96373] WARN: i2c_hid_start [ 0.96382] WARN: i2c_hid_stop [ 0.96395] WARN: i2c_hid_start [ 0.96404] WARN: i2c_hid_stop [ 0.96417] WARN: i2c_hid_start [ 0.96426] WARN: i2c_hid_stop [ 0.96440] WARN: i2c_hid_start [ 0.96450] WARN: i2c_hid_stop [ 0.96464] WARN: i2c_hid_start [ 0.96473] WARN: i2c_hid_stop [ 0.96485] WARN: i2c_hid_start [ 0.96495] WARN: i2c_hid_stop [ 0.96511] WARN: i2c_hid_start [ 0.96522] WARN: i2c_hid_stop [ 0.96537] WARN: i2c_hid_start [ 0.96547] WARN: i2c_hid_stop [ 0.96560] WARN: i2c_hid_start [ 0.96569] WARN: i2c_hid_stop [ 0.96582] WARN: i2c_hid_start [ 0.96591] WARN: i2c_hid_stop [ 0.96603] WARN: i2c_hid_start [ 0.96612] WARN: i2c_hid_stop [ 0.96637] WARN: i2c_hid_start [ 0.96645] WARN: i2c_hid_stop [ 0.96691] WARN: i2c_hid_start [ 0.96709] WARN: i2c_hid_stop [ 0.96727] WARN: i2c_hid_start [ 0.96734] WARN: i2c_hid_stop [ 0.96747] WARN: i2c_hid_start [ 0.96753] WARN: i2c_hid_stop [ 0.96765] WARN: i2c_hid_start [ 0.96774] WARN: i2c_hid_stop [ 0.96791] WARN: i2c_hid_start [ 0.96801] WARN: i2c_hid_stop [ 0.96817] WARN: i2c_hid_start [ 0.96830] WARN: i2c_hid_stop [ 0.96870] WARN: i2c_hid_start [ 0.96884] WARN: i2c_hid_stop [ 0.96909] WARN: i2c_hid_start [ 0.96921] WARN: i2c_hid_stop [ 0.96936] WARN: i2c_hid_start [ 0.96946] WARN: i2c_hid_stop [ 0.96958] WARN: i2c_hid_start [ 0.96967] WARN: i2c_hid_stop [ 0.96978] WARN: i2c_hid_start [ 0.96987] WARN: i2c_hid_stop [ 0.96998] WARN: i2c_hid_start [ 0.97007] WARN: i2c_hid_stop [ 0.97018] WARN: i2c_hid_start [ 0.97027] WARN: i2c_hid_stop [ 0.97039] WARN: i2c_hid_start [ 0.97048] WARN: i2c_hid_stop [ 0.97061] WARN: i2c_hid_start [ 0.97070] WARN: i2c_hid_stop [ 0.97084] WARN: i2c_hid_start [ 0.97093] WARN: i2c_hid_stop [ 0.97106] WARN: i2c_hid_start [ 0.97115] WARN: i2c_hid_stop [ 0.97127] WARN: i2c_hid_start [ 0.97137] WARN: i2c_hid_stop [ 0.97151] WARN: i2c_hid_start [ 0.97161] WARN: i2c_hid_stop [ 0.97184] WARN: i2c_hid_start [ 0.97199] WARN: i2c_hid_stop [ 0.97213] WARN: i2c_hid_start [ 0.97224] WARN: i2c_hid_stop [ 0.97240] WARN: i2c_hid_start [ 0.97249] WARN: i2c_hid_stop [ 0.97263] WARN: i2c_hid_start [ 0.97271] WARN: i2c_hid_stop [ 0.97284] WARN: i2c_hid_start [ 0.97293] WARN: i2c_hid_stop [ 0.97305] WARN: i2c_hid_start [ 0.97314] WARN: i2c_hid_stop [ 0.97327] WARN: i2c_hid_start [ 0.97335] WARN: i2c_hid_stop [ 0.97348] WARN: i2c_hid_start [ 0.97357] WARN: i2c_hid_stop [ 0.97370] WARN: i2c_hid_start [ 0.97379] WARN: i2c_hid_stop [ 0.97391] WARN: i2c_hid_start [ 0.97400] WARN: i2c_hid_stop [ 0.97412] WARN: i2c_hid_start [ 0.97421] WARN: i2c_hid_stop [ 0.97434] WARN: i2c_hid_start [ 0.97447] WARN: i2c_hid_stop [ 0.97461] WARN: i2c_hid_start [ 0.97471] WARN: i2c_hid_stop [ 0.97484] WARN: i2c_hid_start [ 0.97492] WARN: i2c_hid_stop [ 0.97505] WARN: i2c_hid_start [ 0.97514] WARN: i2c_hid_stop [ 0.97526] WARN: i2c_hid_start [ 0.97535] WARN: i2c_hid_stop [ 0.97548] WARN: i2c_hid_start [ 0.97556] WARN: i2c_hid_stop [ 0.97569] WARN: i2c_hid_start [ 0.97578] WARN: i2c_hid_stop [ 0.97590] WARN: i2c_hid_start [ 0.97599] WARN: i2c_hid_stop [ 0.97611] WARN: i2c_hid_start [ 0.97620] WARN: i2c_hid_stop [ 0.97633] WARN: i2c_hid_start [ 0.97642] WARN: i2c_hid_stop [ 0.97654] WARN: i2c_hid_start [ 0.97663] WARN: i2c_hid_stop [ 0.97675] WARN: i2c_hid_start [ 0.97684] WARN: i2c_hid_stop [ 0.97697] WARN: i2c_hid_start [ 0.97706] WARN: i2c_hid_stop [ 0.97719] WARN: i2c_hid_start [ 0.97727] WARN: i2c_hid_stop [ 0.97739] WARN: i2c_hid_start [ 0.97748] WARN: i2c_hid_stop [ 0.97762] WARN: i2c_hid_start [ 0.97769] WARN: i2c_hid_stop [ 0.97784] WARN: i2c_hid_start [ 0.97794] WARN: i2c_hid_stop [ 0.97808] WARN: i2c_hid_start [ 0.97818] WARN: i2c_hid_stop [ 0.97833] WARN: i2c_hid_start [ 0.97842] WARN: i2c_hid_stop [ 0.97866] WARN: i2c_hid_start [ 0.97877] WARN: i2c_hid_stop [ 0.97912] WARN: i2c_hid_start [ 0.97922] WARN: i2c_hid_stop [ 0.97937] WARN: i2c_hid_start [ 0.97945] WARN: i2c_hid_stop [ 0.97959] WARN: i2c_hid_start [ 0.97968] WARN: i2c_hid_stop [ 0.97983] WARN: i2c_hid_start [ 0.97992] WARN: i2c_hid_stop [ 0.98007] WARN: i2c_hid_start [ 0.98015] WARN: i2c_hid_stop [ 0.98031] WARN: i2c_hid_start [ 0.98039] WARN: i2c_hid_stop [ 0.98054] WARN: i2c_hid_start [ 0.98062] WARN: i2c_hid_stop [ 0.98075] WARN: i2c_hid_start [ 0.98085] WARN: i2c_hid_stop [ 0.98098] WARN: i2c_hid_start [ 0.98109] WARN: i2c_hid_stop [ 0.98126] WARN: i2c_hid_start [ 0.98133] WARN: i2c_hid_stop [ 0.98146] WARN: i2c_hid_start [ 0.98156] WARN: i2c_hid_stop [ 0.98168] WARN: i2c_hid_start [ 0.98177] WARN: i2c_hid_stop [ 0.98190] WARN: i2c_hid_start [ 0.98199] WARN: i2c_hid_stop [ 0.98211] WARN: i2c_hid_start [ 0.98221] WARN: i2c_hid_stop [ 0.98236] WARN: i2c_hid_start [ 0.98245] WARN: i2c_hid_stop [ 0.98258] WARN: i2c_hid_start [ 0.98267] WARN: i2c_hid_stop [ 0.98282] WARN: i2c_hid_start [ 0.98292] WARN: i2c_hid_stop [ 0.98310] WARN: i2c_hid_start [ 0.98320] WARN: i2c_hid_stop [ 0.98334] WARN: i2c_hid_start [ 0.98340] WARN: i2c_hid_stop [ 0.98351] WARN: i2c_hid_start [ 0.98360] WARN: i2c_hid_stop [ 0.98376] WARN: i2c_hid_start [ 0.98385] WARN: i2c_hid_stop [ 0.98400] WARN: i2c_hid_start [ 0.98409] WARN: i2c_hid_stop [ 0.98422] WARN: i2c_hid_start [ 0.98431] WARN: i2c_hid_stop [ 0.98447] WARN: i2c_hid_start [ 0.98464] WARN: i2c_hid_stop [ 0.98483] WARN: i2c_hid_start [ 0.98494] WARN: i2c_hid_stop [ 0.98516] WARN: i2c_hid_start [ 0.98527] WARN: i2c_hid_stop [ 0.98540] WARN: i2c_hid_start [ 0.98549] WARN: i2c_hid_stop [ 0.98562] WARN: i2c_hid_start [ 0.98570] WARN: i2c_hid_stop [ 0.98583] WARN: i2c_hid_start [ 0.98592] WARN: i2c_hid_stop [ 0.98603] WARN: i2c_hid_start [ 0.98612] WARN: i2c_hid_stop [ 0.98623] WARN: i2c_hid_start [ 0.98631] WARN: i2c_hid_stop [ 0.98642] WARN: i2c_hid_start [ 0.98651] WARN: i2c_hid_stop [ 0.98662] WARN: i2c_hid_start [ 0.98671] WARN: i2c_hid_stop [ 0.98686] WARN: i2c_hid_start [ 0.98695] WARN: i2c_hid_stop [ 0.98710] WARN: i2c_hid_start [ 0.98721] WARN: i2c_hid_stop [ 0.98739] WARN: i2c_hid_start [ 0.98752] WARN: i2c_hid_stop [ 0.98765] WARN: i2c_hid_start [ 0.98774] WARN: i2c_hid_stop [ 0.98787] WARN: i2c_hid_start [ 0.98795] WARN: i2c_hid_stop [ 0.98810] WARN: i2c_hid_start [ 0.98819] WARN: i2c_hid_stop [ 0.98833] WARN: i2c_hid_start [ 0.98842] WARN: i2c_hid_stop [ 0.98854] WARN: i2c_hid_start [ 0.98863] WARN: i2c_hid_stop [ 0.98873] WARN: i2c_hid_start [ 0.98882] WARN: i2c_hid_stop [ 0.98893] WARN: i2c_hid_start [ 0.98914] WARN: i2c_hid_stop [ 0.98955] WARN: i2c_hid_start [ 0.98961] WARN: i2c_hid_stop [ 0.98982] WARN: i2c_hid_start [ 0.98984] WARN: Lower irq 8 [ 0.98992] WARN: i2c_hid_stop [ 0.99002] WARN: i2c_hid_start [ 0.99007] WARN: i2c_hid_stop [ 0.99037] WARN: i2c_hid_start [ 0.99042] WARN: i2c_hid_stop [ 0.99056] WARN: i2c_hid_start [ 0.99065] WARN: i2c_hid_stop [ 0.99074] WARN: i2c_hid_start [ 0.99079] WARN: i2c_hid_stop [ 0.99097] WARN: i2c_hid_start [ 0.99105] WARN: i2c_hid_stop [ 0.99111] WARN: i2c_hid_start [ 0.99116] WARN: i2c_hid_stop [ 0.99955] WARN: Raise irq 8 [ 1.662] WARN: i2c_hid_start [ 1.670] WARN: i2c_hid_stop [ 1.697] WARN: i2c_hid_start [ 1.707] WARN: i2c_hid_stop [ 1.748] WARN: i2c_hid_start [ 1.758] WARN: i2c_hid_stop [ 1.768] WARN: i2c_hid_start [ 1.773] WARN: i2c_hid_stop [ 1.781] WARN: i2c_hid_start [ 1.790] WARN: i2c_hid_stop [ 1.797] WARN: i2c_hid_start [ 1.803] WARN: i2c_hid_stop [ 1.811] WARN: i2c_hid_start [ 1.819] WARN: i2c_hid_stop [ 1.827] WARN: i2c_hid_start [ 1.836] WARN: i2c_hid_stop [ 1.863] WARN: i2c_hid_start [ 1.872] WARN: i2c_hid_stop [ 1.888] WARN: i2c_hid_start [ 1.897] WARN: i2c_hid_stop [ 1.908] WARN: i2c_hid_start [ 1.917] WARN: i2c_hid_stop [ 1.928] WARN: i2c_hid_start [ 1.934] WARN: i2c_hid_stop [ 1.945] WARN: i2c_hid_start [ 1.954] WARN: i2c_hid_stop [ 1.965] WARN: i2c_hid_start [ 1.974] WARN: i2c_hid_stop [ 1.984] WARN: i2c_hid_start [ 1.993] WARN: i2c_hid_stop [ 1.1004] WARN: i2c_hid_start [ 1.1012] WARN: i2c_hid_stop [ 1.1023] WARN: i2c_hid_start [ 1.1032] WARN: i2c_hid_stop [ 1.1044] WARN: i2c_hid_start [ 1.1052] WARN: i2c_hid_stop [ 1.1064] WARN: i2c_hid_start [ 1.1075] WARN: i2c_hid_stop [ 1.1088] WARN: i2c_hid_start [ 1.1095] WARN: Lower irq 8 [ 1.1096] WARN: i2c_hid_stop [ 1.1107] WARN: i2c_hid_start [ 1.1116] WARN: i2c_hid_stop [ 0.751482] Segment Routing with IPv6 [ 0.755312] In-situ OAM (IOAM) with IPv6 [ 1.1175] WARN: Raise irq 8 [ 1.1843] WARN: i2c_hid_start [ 1.1853] WARN: i2c_hid_stop [ 1.1885] WARN: i2c_hid_start [ 1.1895] WARN: i2c_hid_stop [ 1.1910] WARN: i2c_hid_start [ 1.1919] WARN: i2c_hid_stop [ 1.1932] WARN: i2c_hid_start [ 1.1937] WARN: i2c_hid_stop [ 1.1947] WARN: i2c_hid_start [ 1.1956] WARN: i2c_hid_stop [ 1.1967] WARN: i2c_hid_start [ 1.1976] WARN: i2c_hid_stop [ 1.1987] WARN: i2c_hid_start [ 1.1996] WARN: i2c_hid_stop [ 1.2008] WARN: i2c_hid_start [ 1.2017] WARN: i2c_hid_stop [ 1.2032] WARN: i2c_hid_start [ 1.2041] WARN: i2c_hid_stop [ 1.2054] WARN: i2c_hid_start [ 1.2063] WARN: i2c_hid_stop [ 1.2076] WARN: i2c_hid_start [ 1.2085] WARN: i2c_hid_stop [ 1.2098] WARN: i2c_hid_start [ 1.2107] WARN: i2c_hid_stop [ 1.2120] WARN: i2c_hid_start [ 1.2129] WARN: i2c_hid_stop [ 1.2141] WARN: i2c_hid_start [ 1.2151] WARN: i2c_hid_stop [ 1.2165] WARN: i2c_hid_start [ 1.2174] WARN: i2c_hid_stop [ 1.2184] WARN: i2c_hid_start [ 1.2192] WARN: Lower irq 8 [ 1.2193] WARN: i2c_hid_stop [ 1.2204] WARN: i2c_hid_start [ 1.2212] WARN: i2c_hid_stop [ 0.763253] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver [ 1.2221] WARN: Raise irq 8 [ 1.2517] WARN: i2c_hid_start [ 1.2526] WARN: i2c_hid_stop [ 1.2553] WARN: i2c_hid_start [ 1.2559] WARN: i2c_hid_stop [ 1.2569] WARN: i2c_hid_start [ 1.2579] WARN: i2c_hid_stop [ 1.2590] WARN: i2c_hid_start [ 1.2599] WARN: i2c_hid_stop [ 1.2612] WARN: i2c_hid_start [ 1.2620] WARN: i2c_hid_stop [ 1.2633] WARN: i2c_hid_start [ 1.2641] WARN: i2c_hid_stop [ 1.2653] WARN: i2c_hid_start [ 1.2663] WARN: i2c_hid_stop [ 1.2675] WARN: i2c_hid_start [ 1.2684] WARN: i2c_hid_stop [ 1.2697] WARN: i2c_hid_start [ 1.2705] WARN: i2c_hid_stop [ 1.2717] WARN: i2c_hid_start [ 1.2726] WARN: i2c_hid_stop [ 1.2740] WARN: i2c_hid_start [ 1.2750] WARN: i2c_hid_stop [ 1.2763] WARN: i2c_hid_start [ 1.2772] WARN: i2c_hid_stop [ 1.2785] WARN: i2c_hid_start [ 1.2795] WARN: i2c_hid_stop [ 1.2808] WARN: i2c_hid_start [ 1.2816] WARN: i2c_hid_stop [ 1.2831] WARN: i2c_hid_start [ 1.2840] WARN: i2c_hid_stop [ 1.2852] WARN: i2c_hid_start [ 1.2861] WARN: Lower irq 8 [ 1.2863] WARN: i2c_hid_stop [ 1.2879] WARN: i2c_hid_start [ 1.2889] WARN: i2c_hid_stop [ 0.774423] NET: Registered PF_PACKET protocol family [ 1.3271] WARN: Raise irq 8 [ 1.3327] WARN: i2c_hid_start [ 1.3336] WARN: i2c_hid_stop [ 1.3350] WARN: i2c_hid_start [ 1.3356] WARN: i2c_hid_stop [ 1.3372] WARN: i2c_hid_start [ 1.3380] WARN: i2c_hid_stop [ 1.3391] WARN: i2c_hid_start [ 1.3399] WARN: i2c_hid_stop [ 1.3411] WARN: i2c_hid_start [ 1.3419] WARN: i2c_hid_stop [ 1.3432] WARN: i2c_hid_start [ 1.3441] WARN: i2c_hid_stop [ 1.3457] WARN: i2c_hid_start [ 1.3469] WARN: i2c_hid_stop [ 1.3482] WARN: i2c_hid_start [ 1.3491] WARN: i2c_hid_stop [ 1.3502] WARN: i2c_hid_start [ 1.3511] WARN: i2c_hid_stop [ 1.3523] WARN: i2c_hid_start [ 1.3532] WARN: i2c_hid_stop [ 1.3544] WARN: i2c_hid_start [ 1.3552] WARN: i2c_hid_stop [ 1.3565] WARN: i2c_hid_start [ 1.3574] WARN: i2c_hid_stop [ 1.3593] WARN: i2c_hid_start [ 1.3606] WARN: i2c_hid_stop [ 1.3625] WARN: i2c_hid_start [ 1.3636] WARN: i2c_hid_stop [ 1.3652] WARN: i2c_hid_start [ 1.3660] WARN: i2c_hid_stop [ 1.3672] WARN: i2c_hid_start [ 1.3679] WARN: Lower irq 8 [ 1.3681] WARN: i2c_hid_stop [ 1.3692] WARN: i2c_hid_start [ 1.3701] WARN: i2c_hid_stop [ 1.4444] WARN: Raise irq 8 [ 1.4460] WARN: i2c_hid_start [ 1.4470] WARN: i2c_hid_stop [ 1.4552] WARN: i2c_hid_start [ 1.4565] WARN: i2c_hid_stop [ 1.4584] WARN: i2c_hid_start [ 1.4592] WARN: i2c_hid_stop [ 1.4609] WARN: i2c_hid_start [ 1.4617] WARN: i2c_hid_stop [ 1.4631] WARN: i2c_hid_start [ 1.4639] WARN: i2c_hid_stop [ 1.4651] WARN: i2c_hid_start [ 1.4660] WARN: i2c_hid_stop [ 1.4676] WARN: i2c_hid_start [ 1.4686] WARN: i2c_hid_stop [ 1.4702] WARN: i2c_hid_start [ 1.4711] WARN: i2c_hid_stop [ 1.4723] WARN: i2c_hid_start [ 1.4733] WARN: i2c_hid_stop [ 1.4743] WARN: i2c_hid_start [ 1.4751] WARN: i2c_hid_stop [ 1.4763] WARN: i2c_hid_start [ 1.4771] WARN: i2c_hid_stop [ 1.4781] WARN: i2c_hid_start [ 1.4790] WARN: i2c_hid_stop [ 1.4801] WARN: i2c_hid_start [ 1.4809] WARN: i2c_hid_stop [ 1.4821] WARN: i2c_hid_start [ 1.4830] WARN: i2c_hid_stop [ 1.4841] WARN: i2c_hid_start [ 1.4850] WARN: i2c_hid_stop [ 1.4863] WARN: i2c_hid_start [ 1.4873] WARN: Lower irq 8 [ 1.4875] WARN: i2c_hid_stop [ 1.4889] WARN: i2c_hid_start [ 1.4899] WARN: i2c_hid_stop [ 1.5488] WARN: Raise irq 8 [ 1.5504] WARN: i2c_hid_start [ 1.5513] WARN: i2c_hid_stop [ 1.5571] WARN: i2c_hid_start [ 1.5577] WARN: i2c_hid_start [ 1.5624] WARN: i2c_hid_stop [ 1.5647] WARN: i2c_hid_start [ 1.5653] WARN: i2c_hid_stop [ 1.5667] WARN: i2c_hid_start [ 1.5673] WARN: i2c_hid_start [ 1.5728] WARN: i2c_hid_stop ```

The actual interrupt storm reproduction occurs in window implementation and looks like this:

void fb_window_update(fb_window_t* win)
{
    hid_keyboard_press(win->keyboard, HID_KEY_LEFTCTRL);
    hid_keyboard_release(win->keyboard, HID_KEY_LEFTCTRL);
    ...

Point is, it sometimes manages to pass this and never hangs later on. But sometimes it hangs near i2c-hid init and it can be reproduced with user input. The timings have to be perfect, but it is still possible

X547 commented 6 months ago

I think I need to reproduce it myself. What Linux image/version is used?

LekKit commented 6 months ago

I think I need to reproduce it myself. What Linux image/version is used?

Full setup (firmware/kernel/image). Run as rvvm fw_jump.bin -k Image -i rootfs.ext2, also for the hang to be more likely do this:

void fb_window_update(fb_window_t* win)
{
    for (size_t i=0; i<100000; ++i) {
        hid_keyboard_press(win->keyboard, HID_KEY_LEFTCTRL);
        hid_keyboard_release(win->keyboard, HID_KEY_LEFTCTRL);
    }
    ...

buildroot.zip

X547 commented 6 months ago

It seems I managed to reproduce it and it seems caused by that Linux do not clear interrupt condition or disable interrupt during processing. It stuck in interrupt loop without any I2C IO.

screenshot621

In my Haiku implementation I schedule DPC and disable interrupt, so interrupt is reenabled after DPC processing is finished.

Haiku log:

rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 0xa
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 0x51
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 00
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 00
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 0xa
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 00
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 00
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 00
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 0xa
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 0x51
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 00
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 00
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 0xa
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 00
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
rvvm: irq 8 disabled
rvvm: complete irq 8
i2c_hid_start(is_write: 1)
i2c_hid_write, io_offset: 0, val: 0x3
i2c_hid_write, io_offset: 1, val: 00
  reg: 3
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 00
i2c_hid_read, io_offset: 1
  val: 00
i2c_hid_read, io_offset: 2
  val: 00
i2c_hid_read, io_offset: 3
  val: 00
i2c_hid_read, io_offset: 4
  val: 00
i2c_hid_read, io_offset: 5
  val: 00
i2c_hid_read, io_offset: 6
  val: 00
i2c_hid_read, io_offset: 7
  val: 00
i2c_hid_read, io_offset: 8
  val: 00
i2c_hid_read, io_offset: 9
  val: 00
i2c_hid_stop
rvvm: irq 8 enabled
X547 commented 6 months ago

Interrupt condition should be cleared inside interrupt handler to avoid infinite interrupt loop, but I2C IO also use interrupts, so I can't find any other reliable solution except disabling I2C HID interrupt during processing it in DPC.

X547 commented 6 months ago

Note that in real hardware I2C HID device interrupt pin is usually connected to GPIO controller, not root interrupt controller. Linux may not properly handles cases where GPIO controller is not used. But I feel that using GPIO for I2C HID in emulator is wasteful.

LekKit commented 6 months ago

Interrupt condition should be cleared inside interrupt handler to avoid infinite interrupt loop, but I2C IO also use interrupts, so I can't find any other reliable solution except disabling I2C HID interrupt during processing it in DPC.

So that's apparently a Linux bug? I will try with a newer kernel then.

Upd: Linux 6.7.9 still hangs the same way.

X547 commented 6 months ago

Problem may be caused by missing level triggered interrupt declaration in FDT. Second cell of interrupt controller data can be used to declare interrupt type, 4 is high active level interrupt.

See: https://www.kernel.org/doc/Documentation/devicetree/bindings/interrupt-controller/interrupts.txt

LekKit commented 6 months ago

See: https://www.kernel.org/doc/Documentation/devicetree/bindings/interrupt-controller/interrupts.txt

Passing interrupts = <[IRQ] 4>; or interrupts = <[IRQ] 5>; (I.e. explaining to guest that this IRQ is level-triggered) doesn't fix the issue.

Using plic_send_irq() instead of plic_raise_irq(), plus sending IRQ again if we didn't empty the queue does fix the issue tho, Haiku guests are unaffected. Remind me again please what were the caveats of having edge-triggered I2C-HID interrupts?

X547 commented 6 months ago

Passing interrupts = <[IRQ] 4>; or interrupts = <[IRQ] 5>; (I.e. explaining to guest that this IRQ is level-triggered) doesn't fix the issue.

Have you changed #interrupt-cells to 2?

LekKit commented 6 months ago

Have you changed #interrupt-cells to 2?

Yes

LekKit commented 6 months ago

I think we need to elaborate whether level-triggered interrupts are actually needed. Perhaps Linux driver actually expects edge-triggered interrupts.

X547 commented 6 months ago

Perhaps Linux driver actually expects edge-triggered interrupts.

No. i2c-hid-core.c correctly handle level triggered interrupt by using IRQF_ONESHOT flag and clearing interrupt condition in threaded interrupt handler. Something is wrong with setting PLIC level triggered interrupt mode.

IRQF_ONESHOT - Interrupt is not reenabled after the hardirq handler finished. Used by threaded interrupts which need to keep the irq line disabled until the threaded handler has been run.

LekKit commented 6 months ago

See: https://www.kernel.org/doc/Documentation/devicetree/bindings/interrupt-controller/interrupts.txt

https://www.kernel.org/doc/Documentation/devicetree/bindings/interrupt-controller/sifive%2Cplic-1.0.0.txt

While the PLIC supports both edge-triggered and level-triggered interrupts,
interrupt handlers are oblivious to this distinction and therefore it is not
specified in the PLIC device-tree binding.
X547 commented 6 months ago

What happen if recompile kernel with following change?

https://github.com/torvalds/linux/blob/3aaa8ce7a3350d95b241046ae2401103a4384ba2/drivers/hid/i2c-hid/i2c-hid-core.c#L861

-   if (!irq_get_trigger_type(client->irq))
-       irqflags = IRQF_TRIGGER_LOW;
+   irqflags = IRQF_TRIGGER_HIGH;
X547 commented 6 months ago

Also setting PLIC compatible field to thead,c900-plic and using 2 cells may work.

X547 commented 6 months ago

This patch seems fix problem (includes debug output):

diff --git a/src/devices/eth-oc.c b/src/devices/eth-oc.c
index d1a0974..123b087 100644
--- a/src/devices/eth-oc.c
+++ b/src/devices/eth-oc.c
@@ -543,7 +543,8 @@ PUBLIC rvvm_mmio_handle_t ethoc_init(rvvm_machine_t* machine, tap_dev_t* tap,
     fdt_node_add_prop_reg(ethoc, "reg", base_addr, 0x800);
     fdt_node_add_prop_str(ethoc, "compatible", "opencores,ethoc");
     fdt_node_add_prop_u32(ethoc, "interrupt-parent", plic_get_phandle(plic));
-    fdt_node_add_prop_u32(ethoc, "interrupts", irq);
+    uint32_t interrupt_cells[] = {irq, 4};
+    fdt_node_add_prop_cells(ethoc, "interrupts", interrupt_cells, 2);
     fdt_node_add_child(rvvm_get_fdt_soc(machine), ethoc);
 #endif
     return handle;
diff --git a/src/devices/haiku_window.cpp b/src/devices/haiku_window.cpp
index 1d360d8..9dd215a 100644
--- a/src/devices/haiku_window.cpp
+++ b/src/devices/haiku_window.cpp
@@ -334,6 +334,12 @@ void fb_window_close(fb_window_t* win)

 void fb_window_update(fb_window_t* win)
 {
+#if 0
+    for (size_t i=0; i<100000; ++i) {
+        hid_keyboard_press(win->keyboard, HID_KEY_LEFTCTRL);
+        hid_keyboard_release(win->keyboard, HID_KEY_LEFTCTRL);
+    }
+#endif
     View* view = win->data->wnd->GetView();
     view->LockLooper();
     view->Invalidate();
diff --git a/src/devices/i2c-hid.c b/src/devices/i2c-hid.c
index dd6a809..34ce0c2 100644
--- a/src/devices/i2c-hid.c
+++ b/src/devices/i2c-hid.c
@@ -316,7 +316,7 @@ static bool i2c_hid_start(void* dev, bool is_write)
 {
     i2c_hid_t* i2c_hid = (i2c_hid_t*)dev;
     spin_lock(&i2c_hid->lock);
-    //fprintf(stderr, "i2c_hid_start(is_write: %d)\n", is_write);
+    fprintf(stderr, "i2c_hid_start(is_write: %d)\n", is_write);
     i2c_hid->is_write = is_write;
     i2c_hid->io_offset = 0;
     spin_unlock(&i2c_hid->lock);
@@ -327,15 +327,15 @@ static bool i2c_hid_write(void* dev, uint8_t byte)
 {
     i2c_hid_t* i2c_hid = (i2c_hid_t*)dev;
     spin_lock(&i2c_hid->lock);
-    //fprintf(stderr, "i2c_hid_write, io_offset: %u, val: %#02x\n", i2c_hid->io_offset, byte);
+    fprintf(stderr, "i2c_hid_write, io_offset: %u, val: %#02x\n", i2c_hid->io_offset, byte);
     switch (i2c_hid->io_offset) {
     case 0:
     case 1:
         i2c_hid->reg = bit_replace(i2c_hid->reg, i2c_hid->io_offset*8, 8, byte);
         i2c_hid->io_offset++;
-        //if (i2c_hid->io_offset == 2) {
-        //  fprintf(stderr, "  reg: %u\n", i2c_hid->reg);
-        //}
+        if (i2c_hid->io_offset == 2) {
+          fprintf(stderr, "  reg: %u\n", i2c_hid->reg);
+        }
         break;
     default:
         if (i2c_hid_write_reg(i2c_hid, i2c_hid->reg, i2c_hid->io_offset - 2, byte))
@@ -352,9 +352,9 @@ static bool i2c_hid_read(void* dev, uint8_t* byte)
 {
     i2c_hid_t* i2c_hid = (i2c_hid_t*)dev;
     spin_lock(&i2c_hid->lock);
-    //fprintf(stderr, "i2c_hid_read, io_offset: %u\n", i2c_hid->io_offset);
+    fprintf(stderr, "i2c_hid_read, io_offset: %u\n", i2c_hid->io_offset);
     *byte = i2c_hid_read_reg(i2c_hid, i2c_hid->reg, i2c_hid->io_offset++);
-    //fprintf(stderr, "  val: %#02x\n", *byte);
+    fprintf(stderr, "  val: %#02x\n", *byte);
     spin_unlock(&i2c_hid->lock);
     return true;
 }
@@ -363,7 +363,7 @@ static void i2c_hid_stop(void* dev)
 {
     i2c_hid_t* i2c_hid = (i2c_hid_t*)dev;
     spin_lock(&i2c_hid->lock);
-    //fprintf(stderr, "i2c_hid_stop\n");
+    fprintf(stderr, "i2c_hid_stop\n");
     i2c_hid->is_reset = false;
     if (i2c_hid->command == I2C_HID_COMMAND_RESET) i2c_hid_reset(i2c_hid, false);
     i2c_hid->reg = I2C_HID_INPUT_REG;
@@ -412,7 +412,8 @@ static void i2c_hid_init(rvvm_machine_t* machine, i2c_bus_t* bus, uint16_t addr,
     fdt_node_add_prop_u32(i2c_fdt, "reg", addr);
     fdt_node_add_prop_u32(i2c_fdt, "hid-descr-addr", I2C_HID_DESC_REG);
     fdt_node_add_prop_u32(i2c_fdt, "interrupt-parent", plic_get_phandle(plic));
-    fdt_node_add_prop_u32(i2c_fdt, "interrupts", irq);
+    uint32_t interrupt_cells[] = {irq, 4};
+    fdt_node_add_prop_cells(i2c_fdt, "interrupts", interrupt_cells, 2);
     fdt_node_add_child(i2c_bus_fdt_node(bus), i2c_fdt);
 #endif
 }
diff --git a/src/devices/i2c-oc.c b/src/devices/i2c-oc.c
index c12ac31..3535476 100644
--- a/src/devices/i2c-oc.c
+++ b/src/devices/i2c-oc.c
@@ -225,7 +225,8 @@ PUBLIC i2c_bus_t* i2c_oc_init(rvvm_machine_t* machine, rvvm_addr_t base_addr, pl
     fdt_node_add_prop_reg(i2c_fdt, "reg", base_addr, I2C_OC_REG_SIZE);
     fdt_node_add_prop_str(i2c_fdt, "compatible", "opencores,i2c-ocores");
     fdt_node_add_prop_u32(i2c_fdt, "interrupt-parent", plic_get_phandle(plic));
-    fdt_node_add_prop_u32(i2c_fdt, "interrupts", irq);
+    uint32_t interrupt_cells[] = {irq, 4};
+    fdt_node_add_prop_cells(i2c_fdt, "interrupts", interrupt_cells, 2);
     fdt_node_add_prop_u32(i2c_fdt, "clocks", fdt_node_get_phandle(i2c_clock));
     fdt_node_add_prop_str(i2c_fdt, "clock-names", "clk");
     fdt_node_add_prop_u32(i2c_fdt, "reg-shift", 2);
diff --git a/src/devices/ns16550a.c b/src/devices/ns16550a.c
index 478ef47..c078b50 100644
--- a/src/devices/ns16550a.c
+++ b/src/devices/ns16550a.c
@@ -230,7 +230,8 @@ PUBLIC rvvm_mmio_handle_t ns16550a_init(rvvm_machine_t* machine, chardev_t* char
     fdt_node_add_prop_str(uart_fdt, "status", "okay");
     if (plic) {
         fdt_node_add_prop_u32(uart_fdt, "interrupt-parent", plic_get_phandle(plic));
-        fdt_node_add_prop_u32(uart_fdt, "interrupts", irq);
+        uint32_t interrupt_cells[] = {irq, 4};
+        fdt_node_add_prop_cells(uart_fdt, "interrupts", interrupt_cells, 2);
     }
     fdt_node_add_child(rvvm_get_fdt_soc(machine), uart_fdt);
 #endif
diff --git a/src/devices/pci-bus.c b/src/devices/pci-bus.c
index 3ead12f..cc0e1c0 100644
--- a/src/devices/pci-bus.c
+++ b/src/devices/pci-bus.c
@@ -295,25 +295,25 @@ PUBLIC pci_bus_t* pci_bus_init(rvvm_machine_t* machine, plic_ctx_t* plic, uint32
     // Crossing-style IRQ routing for IRQ balancing
     // INTA of dev 2 routes the same way as INTB of dev 1, etc
     uint32_t plic_handle = plic_get_phandle(plic);
-    uint32_t interrupt_map[96] = {
-        0x0000, 0, 0, 1, plic_handle, bus->irq[0],
-        0x0000, 0, 0, 2, plic_handle, bus->irq[1],
-        0x0000, 0, 0, 3, plic_handle, bus->irq[2],
-        0x0000, 0, 0, 4, plic_handle, bus->irq[3],
-        0x0800, 0, 0, 1, plic_handle, bus->irq[1],
-        0x0800, 0, 0, 2, plic_handle, bus->irq[2],
-        0x0800, 0, 0, 3, plic_handle, bus->irq[3],
-        0x0800, 0, 0, 4, plic_handle, bus->irq[0],
-        0x1000, 0, 0, 1, plic_handle, bus->irq[2],
-        0x1000, 0, 0, 2, plic_handle, bus->irq[3],
-        0x1000, 0, 0, 3, plic_handle, bus->irq[0],
-        0x1000, 0, 0, 4, plic_handle, bus->irq[1],
-        0x1800, 0, 0, 1, plic_handle, bus->irq[3],
-        0x1800, 0, 0, 2, plic_handle, bus->irq[0],
-        0x1800, 0, 0, 3, plic_handle, bus->irq[2],
-        0x1800, 0, 0, 4, plic_handle, bus->irq[1],
+    uint32_t interrupt_map[112] = {
+        0x0000, 0, 0, 1, plic_handle, bus->irq[0], 4,
+        0x0000, 0, 0, 2, plic_handle, bus->irq[1], 4,
+        0x0000, 0, 0, 3, plic_handle, bus->irq[2], 4,
+        0x0000, 0, 0, 4, plic_handle, bus->irq[3], 4,
+        0x0800, 0, 0, 1, plic_handle, bus->irq[1], 4,
+        0x0800, 0, 0, 2, plic_handle, bus->irq[2], 4,
+        0x0800, 0, 0, 3, plic_handle, bus->irq[3], 4,
+        0x0800, 0, 0, 4, plic_handle, bus->irq[0], 4,
+        0x1000, 0, 0, 1, plic_handle, bus->irq[2], 4,
+        0x1000, 0, 0, 2, plic_handle, bus->irq[3], 4,
+        0x1000, 0, 0, 3, plic_handle, bus->irq[0], 4,
+        0x1000, 0, 0, 4, plic_handle, bus->irq[1], 4,
+        0x1800, 0, 0, 1, plic_handle, bus->irq[3], 4,
+        0x1800, 0, 0, 2, plic_handle, bus->irq[0], 4,
+        0x1800, 0, 0, 3, plic_handle, bus->irq[2], 4,
+        0x1800, 0, 0, 4, plic_handle, bus->irq[1], 4,
     };
-    fdt_node_add_prop_cells(pci_node, "interrupt-map", interrupt_map, 96);
+    fdt_node_add_prop_cells(pci_node, "interrupt-map", interrupt_map, 112);

     uint32_t interrupt_mask[4] = { 0x1800, 0, 0, 7 };
     fdt_node_add_prop_cells(pci_node, "interrupt-map-mask", interrupt_mask, 4);
diff --git a/src/devices/plic.c b/src/devices/plic.c
index 1e36ee2..c13e674 100644
--- a/src/devices/plic.c
+++ b/src/devices/plic.c
@@ -23,6 +23,8 @@ along with this program.  If not, see <https://www.gnu.org/licenses/>.
 #include "mem_ops.h"
 #include "atomics.h"

+#include <stdio.h>
+
 #define PLIC_CTXFLAG_THRESHOLD     0x0
 #define PLIC_CTXFLAG_CLAIMCOMPLETE 0x1

@@ -157,6 +159,7 @@ static uint32_t plic_claim_irq(plic_ctx_t* plic, uint32_t ctx)
 static void plic_complete_irq(plic_ctx_t* plic, uint32_t ctx, uint32_t irq)
 {
     uint32_t raised = atomic_load_uint32(&plic->raised[irq >> 5]) & (1U << (irq & 0x1F));
+    fprintf(stderr, "rvvm: complete irq %" PRIu32 "\n", irq);
     if (raised) {
         // Rearm raised interrupt as pending after completion
         atomic_or_uint32(&plic->pending[irq >> 5], raised);
@@ -217,6 +220,7 @@ static bool plic_mmio_write(rvvm_mmio_dev_t* dev, void* data, size_t offset, uin
         uint32_t irq = offset >> 2;
         if (irq > 0 && irq < PLIC_SOURCE_MAX) {
             atomic_store_uint32(&plic->prio[irq], read_uint32_le(data));
+               fprintf(stderr, "rvvm: irq priority %" PRIu32 "\n", plic->prio[irq]);
             plic_update_irq(plic, irq);
         }
     } else if (offset < 0x1080) {
@@ -228,7 +232,17 @@ static bool plic_mmio_write(rvvm_mmio_dev_t* dev, void* data, size_t offset, uin
         uint32_t reg = ((offset - 0x2000) >> 2) & 0x1F;
         uint32_t ctx = (offset - 0x2000) >> 7;
         if (reg < PLIC_SRC_REG_COUNT && ctx < plic_ctx_count(plic)) {
+            uint32_t oldEnable = plic->enable[ctx][reg];
             atomic_store_uint32(&plic->enable[ctx][reg], read_uint32_le(data));
+            uint32_t enable = plic->enable[ctx][reg];
+            for (uint32_t i = 0; i < 32; i++) {
+               uint32_t mask = 1 << i;
+               if ((oldEnable & mask) == 0 && (enable & mask) != 0)
+                   fprintf(stderr, "rvvm: irq %" PRIu32 " enabled\n", 32*reg + i);
+
+               if ((oldEnable & mask) != 0 && (enable & mask) == 0)
+                   fprintf(stderr, "rvvm: irq %" PRIu32 " disabled\n", 32*reg + i);
+            }
             plic_update_ctx_irq_reg(plic, ctx, reg);
         }
     } else if (offset < 0x200000) {
@@ -242,6 +256,7 @@ static bool plic_mmio_write(rvvm_mmio_dev_t* dev, void* data, size_t offset, uin
                 plic_complete_irq(plic, ctx, read_uint32_le(data));
             } else if (flag == PLIC_CTXFLAG_THRESHOLD) {
                 atomic_store_uint32(&plic->threshold[ctx], read_uint32_le(data));
+                   fprintf(stderr, "rvvm: irq threshold %" PRIu32 "\n", plic->threshold[ctx]);
                 plic_update_ctx(plic, ctx);
             }
         }
@@ -323,9 +338,9 @@ PUBLIC plic_ctx_t* plic_init(rvvm_machine_t* machine, rvvm_addr_t base_addr)
     }

     struct fdt_node* plic_node = fdt_node_create_reg("plic", base_addr);
-    fdt_node_add_prop_u32(plic_node, "#interrupt-cells", 1);
+    fdt_node_add_prop_u32(plic_node, "#interrupt-cells", 2);
     fdt_node_add_prop_reg(plic_node, "reg", base_addr, 0x4000000);
-    fdt_node_add_prop_str(plic_node, "compatible", "sifive,plic-1.0.0");
+    fdt_node_add_prop_str(plic_node, "compatible", "thead,c900-plic");
     fdt_node_add_prop_u32(plic_node, "riscv,ndev", PLIC_SOURCE_MAX - 1);
     fdt_node_add_prop(plic_node, "interrupt-controller", NULL, 0);
     fdt_node_add_prop_cells(plic_node, "interrupts-extended", irq_ext, vector_size(machine->harts) * 4);
diff --git a/src/devices/ps2-altera.c b/src/devices/ps2-altera.c
index ad2dcb8..7d46b94 100644
--- a/src/devices/ps2-altera.c
+++ b/src/devices/ps2-altera.c
@@ -137,7 +137,8 @@ void altps2_init(rvvm_machine_t* machine, rvvm_addr_t base_addr, plic_ctx_t* pli
     fdt_node_add_prop_reg(ps2, "reg", base_addr, ALTPS2_MMIO_SIZE);
     fdt_node_add_prop_str(ps2, "compatible", "altr,ps2-1.0");
     fdt_node_add_prop_u32(ps2, "interrupt-parent", plic_get_phandle(plic));
-    fdt_node_add_prop_u32(ps2, "interrupts", irq);
+    uint32_t interrupt_cells[] = {irq, 4};
+    fdt_node_add_prop_cells(ps2, "interrupts", interrupt_cells, 2);
     fdt_node_add_child(rvvm_get_fdt_soc(machine), ps2);
 #endif
 }
diff --git a/src/devices/rtc-goldfish.c b/src/devices/rtc-goldfish.c
index e71f27a..2a868fa 100644
--- a/src/devices/rtc-goldfish.c
+++ b/src/devices/rtc-goldfish.c
@@ -130,7 +130,8 @@ PUBLIC rvvm_mmio_handle_t rtc_goldfish_init(rvvm_machine_t* machine, rvvm_addr_t
     fdt_node_add_prop_reg(rtc, "reg", base_addr, RTC_REG_SIZE);
     fdt_node_add_prop_str(rtc, "compatible", "google,goldfish-rtc");
     fdt_node_add_prop_u32(rtc, "interrupt-parent", plic_get_phandle(plic));
-    fdt_node_add_prop_u32(rtc, "interrupts", irq);
+    uint32_t interrupt_cells[] = {irq, 4};
+    fdt_node_add_prop_cells(rtc, "interrupts", interrupt_cells, 2);
     fdt_node_add_child(rvvm_get_fdt_soc(machine), rtc);
 #endif
     return handle;
X547 commented 6 months ago

Linux log:

rvvm: irq priority 0
rvvm: complete irq 9
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 0x8
rvvm: complete irq 5
i2c_hid_read, io_offset: 1
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 2
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 3
  val: 0x33
rvvm: complete irq 5
i2c_hid_read, io_offset: 4
  val: 0xd
rvvm: complete irq 5
i2c_hid_read, io_offset: 5
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 6
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 7
  val: 00
rvvm: complete irq 5
i2c_hid_stop
rvvm: complete irq 5
rvvm: complete irq 5
rvvm: irq priority 1
rvvm: irq priority 0
rvvm: complete irq 9
i2c_hid_start(is_write: 0)
i2c_hid_read, io_offset: 0
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 1
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 2
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 3
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 4
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 5
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 6
  val: 00
rvvm: complete irq 5
i2c_hid_read, io_offset: 7
  val: 00
rvvm: complete irq 5
i2c_hid_stop
rvvm: complete irq 5
rvvm: complete irq 5
rvvm: irq priority 1
rvvm: complete irq 2
LekKit commented 6 months ago

Also setting PLIC compatible field to thead,c900-plic and using 2 cells may work.

In reality THead PLIC is subtly non spec conformant, and has a quirk PLIC_QUIRK_EDGE_INTERRUPT in kernel driver. Because of that quirk it has to encode actual interrupt behavior as two cells, and only for those chips kernel will decode it that way, as seen here: https://elixir.bootlin.com/linux/latest/source/drivers/irqchip/irq-sifive-plic.c#L327 (Which is why it didn't work when I tried it originally). But this helps with debugging for now; I'll see what actually changes in kernel with this and perhaps either fix it or conclude it's a kernel bug with detailed info for a mailing list.

X547 commented 6 months ago

But this helps with debugging for now; I'll see what actually changes in kernel with this and perhaps either fix it or conclude it's a kernel bug with detailed info for a mailing list.

IRQF_ONESHOT flag do not work without IRQF_TRIGGER_HIGH/IRQF_TRIGGER_LOW setting, which can't be set without PLIC_QUIRK_EDGE_INTERRUPT in current Linux PLIC driver code.

LekKit commented 6 months ago

But this helps with debugging for now; I'll see what actually changes in kernel with this and perhaps either fix it or conclude it's a kernel bug with detailed info for a mailing list.

IRQF_ONESHOT flag do not work without IRQF_TRIGGER_HIGH/IRQF_TRIGGER_LOW setting, which can't be set without PLIC_QUIRK_EDGE_INTERRUPT in current Linux PLIC driver code.

So basically an incompatibility of I2C-HID & SiFive PLIC?

X547 commented 6 months ago

So basically an incompatibility of I2C-HID & PLIC?

I think it is a Linux bug in PLIC driver so it do not properly support level triggered interrupts. Even if edge/level is hardcoded as hardware level, software still should know interrupt type for proper operation. I think that 2 interrupt cells should be always able to be specified, not only for T-Head PLIC.

As I understand real hardware SiFive PLIC do not expose interrupt pins outside of chip, so GPIO is the only option without redesigning hardware is to connect I2C HID device interrupt line.

Problem should be not present with APLIC because it supports software configurable interrupt types.

LekKit commented 6 months ago

I will be heading to RISC-V Linux mailing list today to report this. Thanks for your cooperation.

Hopefully they will not reject this; If they do, it will either be wontfix or we'll have to route I2C-HID IRQ line through SiFive GPIO (Which in turn will require changes on Haiku side?)

X547 commented 6 months ago

SiFive GPIO (Which in turn will require changes on Haiku side?)

Yes, but it is doable.

LekKit commented 6 months ago

Yes, but it is doable.

If Haiku already has the infrastructure to route GPIO IRQs to I2C-HID (Which it should, as that's how most HW works), then it's a matter of adding SiFive GPIO driver which is not a complicated device at all. In future I can add JH7110 GPIO, etc on RVVM side.

LekKit commented 6 months ago

It appears switching to THead PLIC fixes this for different reasons. I've checked all changes PLIC_QUIRK_EDGE_INTERRUPT makes in the driver, and removing those 2 lines fixes the issues without patching RVVM.

https://elixir.bootlin.com/linux/latest/source/drivers/irqchip/irq-sifive-plic.c#L223

The issue is not fixed if I keep this return path enabled for THead PLIC and build RVVM with your patch... So perhaps a bug in RVVM PLIC? Altho I can't see how, really.

X547 commented 6 months ago

So perhaps a bug in RVVM PLIC? Altho I can't see how, really.

If there are no log output rvvm: irq xxx priority 0/1 or rvvm: irq xxx enabled/disabled on each I2C HID IO transaction, it is definitely a software bug (wrong FDT definitions and/or Linux bug), not a problem of hardware emulation.

Also maybe SiFive PLIC is not supposed to support level-triggered interrupts at all, so it do not fully support features of PLIC spec. So setting T-Head PLIC may be not a bad choice.

X547 commented 6 months ago

Did you ask Linux kernel community about problem? If so, can you share a link?

LekKit commented 6 months ago

Did you ask Linux kernel community about problem? If so, can you share a link?

Sorry I postponed this because I was still debugging related things. You can report this independently if you want, to riscv-linux mailing list, I am really sloppy with this. Or should I instead hurry with this?

X547 commented 6 months ago

No hurry, just asked.

LekKit commented 6 months ago

https://lists.infradead.org/pipermail/linux-riscv/2024-March/050429.html

I do hope that someone there will provide an explanation what the return path at irq-sivive-plic.c@223 does and possible fix in the kernel or perhaps a hint what (if anything) could be still wrong on RVVM side

LekKit commented 6 months ago

I also figured that advertising THead PLIC in RVVM is not really a good idea moving forward, because it has additional functionality used by the M-mode firmware which we don't implement (kernel side changes are less invasive) , and it could break in future

LekKit commented 6 months ago

Should I release a stable v0.6 in the meantime? It seems there are no immediate clues on the mailing list about what's wrong, but I also don't see what else we can do on the VM side.

Touching any PLIC/I2C-HID code at all right now seems not very wise because kernel dev (hopefuly) will be looking into this issue and they will not be pleased if we make random changes now. Having a stable v0.6 release also saves them from accidentally using v0.5 which is a year old by now. If anything comes up on the VM side, we can backport changes to i.e. v0.6.1

X547 commented 6 months ago

Should I release a stable v0.6 in the meantime?

It would be nice to fix keymappings in Haiku window backend before release. Some keys on Japanese keyboard are currently not mapped and ignored.

Reference code: https://github.com/X547/wayland-server/blob/1a8d982304077fb95f4de395b911466efbf343c3/HaikuSeat.cpp#L29

LekKit commented 6 months ago

It would be nice to fix keymappings in Haiku window backend before release. Some keys on Japanese keyboard are currently not mapped and ignored.

Are there any other backends that are affected, or any other keys that were possibly left forgotten? I have a German keyboard without a numpad on my laptop, and a few usual UK/US-like keyboards so I don't even know what other keys exist honestly. So maybe I should just look at hid spec again

X547 commented 6 months ago

So maybe I should just look at hid spec again

HID to Haiku key code table: https://github.com/haiku/haiku/blob/a40cec84d61652d527ed800dc7653fc8706ad17b/src/add-ons/kernel/drivers/input/hid_shared/KeyboardProtocolHandler.cpp#L586

LekKit commented 6 months ago

Added international keys & many more other keycodes into hid_api in 48920ee. Window implementations will follow soon.

LekKit commented 6 months ago

Please test a4baaee (I don't even have a keyboard with such keys). I hope it works.

LekKit commented 6 months ago

It seems that Windows maps both Japanese keyboard ro (ろ) and German kerboard <>| (Right next to the lshift, but honestly I don't use it a lot) to the same keycode VK_OEM_102. However, they are different keycodes in HID spec & RVVM API (HID_KEY_RO and HID_KEY_102ND respectively). I dunno what to do with this because WinAPI has no easy way to distinguish them from userspace.

However, it seems I got how to implement HID_KEY_KATAKANAHIRAGANA, HID_KEY_HENKAN, HID_KEY_MUHENKAN. Perhaps I can drop the German <>| variant on Windows and unconditionally send HID_KEY_RO to the guest.

UPD: 4754f08

X547 commented 6 months ago

I dunno what to do with this because WinAPI has no easy way to distinguish them from userspace.

Windows also send PS/2 scancodes for keyboard messages, even if keyboard is USB.

LekKit commented 6 months ago

Windows also send PS/2 scancodes for keyboard messages, even if keyboard is USB.

Oh well, thanks. I thought this was some kind of weird driver-specific mechanism but it seems this even works in Wine. I guess I will implement this.

Implemented full HID international keys support on X11 in 86ecb24, and on SDL2 in 82a8b39. SDL2 doesn't seem to have 102ND keycode tho (that German <>| one), or perhaps I missed something. SDL1 lacks any kind of international key support.

There are also multimedia keys (Vol+-, brightness, screen locking) that I don't really want being sent to the guest (When user presses Vol+ it would be handled by both host & guest systems which is weird). Idk what to do with this for now, but at least we have the definitions for them in hid_api for now.

LekKit commented 6 months ago

Nam Cao pinged me on the mailing list about the possible solution about the I2C-HID hang. I'll be testing the kernel patch right now.