To try to keep subject lines straight, I took a cue from Andreas and started a new thread specifically to have to do with the KMI getting a bad command.
Here are some DPRINTFs with the Interrupts and Pl050 debug flags turned on, along with some annotation explaining what I think is happening. 1892000000000: system.platform.kmi1: Read Status: 0x43 The kernel checks the KMISTAT register to see if TXEMPTY is set. This happens in amba_kmi_write in drivers/input/serio/ambakmi.c. It is, so that function doesn't wait and continues on to the part that actually writes data. 1892000000000: system.platform.kmi1: Write Data: 0xe8 The kernel sends the 0xe8 command which is "SetResolution" according to gem5's ps2.hh. That command takes one byte as an argument which has the resolution to use. 1892003000000: system.platform.kmi1: Generate Interrupt: rawInt=0x3 ctrl=0x14 int=0x1 1892003000000: system.platform.gic: Set SPI 45 1892003000000: system.platform.kmi1: -- Generated The KMI model in gem5 decides that it both wants to send the RX interrupt, and that it's enabled. It notifies the GIC. 1893000000000: system.platform.kmi1: Read Interrupts: 0x1 In the KMI interrupt handler, amba_kmi_int in drivers/input/serio/ambakmi.c, the kernel reads the KMIIR register to determine which interrupt happened (RX or TX). The value indicates it was an RX interrupt. 1893000000000: system.platform.gic: Clear SPI 45 1893000000000: system.platform.kmi1: Read Data: 0xfa As part of reading the KMIDATA register, the interrupt is cleared (the GIC agrees). The model returns 0xfa, which is the PS/2 code for "ACK" to show that it received and recognizes the command. 1893000000000: system.platform.kmi1: Read Interrupts: 0 The loop in that function checks the KMIIR register again and sees that the interrupt is now cleared. The RX buffer has been read, and the mouse has not yet transmitted the next byte into the buffer. (I modified how the KMI model works a bit, see a patch I'll upload shortly) 1893000000000: system.platform.kmi1: Read Status: 0x43 1893000000000: system.platform.kmi1: Write Data: 0 As before, the kernel sends a byte to the KMI. This is the parameter for the SetResolution command sent earlier. 1893003000000: system.platform.kmi1: Generate Interrupt: rawInt=0x3 ctrl=0x14 int=0x1 1893003000000: system.platform.gic: Set SPI 45 1893003000000: system.platform.kmi1: -- Generated 1894000000000: system.platform.kmi1: Read Interrupts: 0x1 1894000000000: system.platform.gic: Clear SPI 45 1894000000000: system.platform.kmi1: Read Data: 0xfa 1894000000000: system.platform.kmi1: Read Interrupts: 0 Again as before, the KMI responds with "ACK". 1894000000000: system.platform.kmi1: Read Status: 0x43 1894000000000: system.platform.kmi1: Write Data: 0xf3 The kernel sends a 0xf3 byte which is "SetRate". That command also takes one byte which is the rate to set. 1894003000000: system.platform.kmi1: Generate Interrupt: rawInt=0x3 ctrl=0x14 int=0x1 1894003000000: system.platform.gic: Set SPI 45 1894003000000: system.platform.kmi1: -- Generated 1895000000000: system.platform.kmi1: Read Interrupts: 0x1 1895000000000: system.platform.gic: Clear SPI 45 1895000000000: system.platform.kmi1: Read Data: 0xfa 1895000000000: system.platform.kmi1: Read Interrupts: 0 The KMI replies with "ACK". 1901000000000: system.platform.kmi1: Read Status: 0x43 1901000000000: system.platform.kmi1: Write Data: 0xf3 For some reason, the kernel again sends 0xf3 which is the same "SetRate" command. Because this came immediately after the previous "SetRate", this is treated as the argument and not a separate command. 1901003000000: system.platform.kmi1: Generate Interrupt: rawInt=0x3 ctrl=0x14 int=0x1 1901003000000: system.platform.gic: Set SPI 45 1901003000000: system.platform.kmi1: -- Generated 1902000000000: system.platform.kmi1: Read Interrupts: 0x1 1902000000000: system.platform.gic: Clear SPI 45 1902000000000: system.platform.kmi1: Read Data: 0xfa 1902000000000: system.platform.kmi1: Read Interrupts: 0 The KMI thinks this is a rate to set, and since it doesn't model that it basically tells the kernel "Sure, whatever" and replies with an "ACK". 1902000000000: system.platform.kmi1: Read Status: 0x43 1902000000000: system.platform.kmi1: Write Data: 0x3c The kernel sends the KMI another byte which I think is supposed to be the parameter of the above "SetRate". Because the KMI is expecting a command, it looks to see if it knows how to do 0x3c. It does not. Originally this would panic gem5, but I've modified it for now to return a "NAK", and modified the kernel to panic when it gets a NAK-ed response from a PS/2 device. 1902003000000: system.platform.kmi1: Generate Interrupt: rawInt=0x3 ctrl=0x14 int=0x1 1902003000000: system.platform.gic: Set SPI 45 1902003000000: system.platform.kmi1: -- Generated 1903000000000: system.platform.kmi1: Read Interrupts: 0x1 1903000000000: system.platform.gic: Clear SPI 45 1903000000000: system.platform.kmi1: Read Data: 0xfe 1903000000000: system.platform.kmi1: Read Interrupts: 0 The KMI sends the NAK, and the kernel panics. The panic output from the kernel is the following: [ 136.335592] Kernel panic - not syncing: Actual nak from PS2 device? [ 136.335592] [ 136.335599] CPU: 1 PID: 390 Comm: kworker/1:1 Not tainted 4.4.76+ #8 [ 136.335600] Hardware name: V2P-AARCH64 (DT) [ 136.335623] Workqueue: events_long serio_handle_event [ 136.335625] Call trace: [ 136.335633] [<ffffff8008089f18>] dump_backtrace+0x0/0x1e8 [ 136.335636] [<ffffff800808a124>] show_stack+0x24/0x30 [ 136.335641] [<ffffff80083b1ac4>] dump_stack+0x90/0xb4 [ 136.335696] [<ffffff80081a78a0>] panic+0xe4/0x228 [ 136.335704] [<ffffff80085c4e58>] ps2_sendbyte+0x188/0x1a0 [ 136.335706] [<ffffff80085c5144>] __ps2_command+0xec/0x3e8 [ 136.335708] [<ffffff80085c548c>] ps2_command+0x4c/0x78 [ 136.335712] [<ffffff80085d1d6c>] thinking_detect+0x8c/0x108 [ 136.335714] [<ffffff80085d2658>] psmouse_extensions+0x238/0x448 [ 136.335716] [<ffffff80085d2984>] psmouse_switch_protocol+0x11c/0x1a0 [ 136.335719] [<ffffff80085d365c>] psmouse_connect+0x284/0x300 [ 136.335721] [<ffffff80085c47c0>] serio_driver_probe+0x40/0x60 [ 136.335725] [<ffffff80085263b0>] driver_probe_device+0xd0/0x2e8 [ 136.335727] [<ffffff800852667c>] __driver_attach+0xb4/0xb8 [ 136.335729] [<ffffff8008524234>] bus_for_each_dev+0x5c/0xa8 [ 136.335731] [<ffffff8008525d10>] driver_attach+0x30/0x40 [ 136.335733] [<ffffff80085c4404>] serio_handle_event+0xe4/0x230 [ 136.335736] [<ffffff80080d764c>] process_one_work+0x1dc/0x4c8 [ 136.335738] [<ffffff80080d7a64>] worker_thread+0x12c/0x4b0 [ 136.335741] [<ffffff80080de54c>] kthread+0xfc/0x100 [ 136.335744] [<ffffff8008084e90>] ret_from_fork+0x10/0x40 [ 136.353261] CPU0: stopping [ 136.353268] CPU: 0 PID: 576 Comm: kworker/0:1 Not tainted 4.4.76+ #8 [ 136.353270] Hardware name: V2P-AARCH64 (DT) [ 136.353315] Workqueue: events_power_efficient fb_flashcursor [ 136.353316] Call trace: [ 136.353323] [<ffffff8008089f18>] dump_backtrace+0x0/0x1e8 [ 136.353326] [<ffffff800808a124>] show_stack+0x24/0x30 [ 136.353330] [<ffffff80083b1ac4>] dump_stack+0x90/0xb4 [ 136.353333] [<ffffff800808f6f0>] handle_IPI+0x328/0x350 [ 136.353335] [<ffffff800808158c>] gic_handle_irq+0xac/0xb0 [ 136.353337] Exception stack(0xffffffc0bffb6fd0 to 0xffffffc0bffb7100) [ 136.353339] 6fc0: ffffffc07390fb60 0000008000000000 [ 136.353341] 6fe0: ffffffc07390fc90 ffffff80081169d0 0000000040000145 0000000000000000 [ 136.353343] 7000: ffffffc07390fc90 ffffffc07390fb60 0000000000000000 0000000000000000 [ 136.353344] 7020: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 136.353346] 7040: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 136.353348] 7060: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 136.353349] 7080: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 136.353351] 70a0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 136.353352] 70c0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 136.353354] 70e0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 136.353356] [<ffffff80080847b4>] el1_irq+0xb4/0x128 [ 136.353370] [<ffffff80081169d0>] console_unlock+0x298/0x4c0 [ 136.353373] [<ffffff800840cb40>] fb_flashcursor+0x148/0x160 [ 136.353376] [<ffffff80080d764c>] process_one_work+0x1dc/0x4c8 [ 136.353377] [<ffffff80080d7a64>] worker_thread+0x12c/0x4b0 [ 136.353380] [<ffffff80080de54c>] kthread+0xfc/0x100 [ 136.353383] [<ffffff8008084e90>] ret_from_fork+0x10/0x40 [ 136.354249] Kernel Offset: disabled [ 136.354251] Memory Limit: 3072 MB [ 138.468588] ---[ end Kernel panic - not syncing: Actual nak from PS2 device? [ 138.468588] If you take a look at the "thinking_detect" function in drivers/input/mouse/psmouse-base.c, you'll see that it attempts to use a series of "SetResolution" and "SetRate" commands as a magic handshake to trigger a special mode in the Kensington ThinkingMouse which would then change its ID and reveal its identity. Normally all of those commands would be odd but legal and harmless, and an unaware mouse would receive them and just keep working normally. Unfortunately, it looks like those commands got garbled. Specifically, it looks like the "20" parameter of the first PSMOUSE_CMD_SETRATE ps2_command got dropped, and what the KMI saw was the second one which should have a parameter of "60" which is 0x3c, the unrecognized command. One thing this doesn't explain is why the kernel skipped over that parameter. All the handshaking looks correct, with the kernel going through the motions of recognizing each interrupt, checking for an empty TX buffer, etc. Another interesting symptom is that I also instrumented the kernel to report when it didn't think it got a response from the PS/2 device. That was triggered by that same function immediately before the panic: [ 134.796033] Call trace: [ 134.814856] [<ffffff8008089f18>] dump_backtrace+0x0/0x1e8 [ 134.849598] [<ffffff800808a124>] show_stack+0x24/0x30 [ 136.299173] [<ffffff80083b1ac4>] dump_stack+0x90/0xb4 [ 136.299190] [<ffffff80085c4e5c>] ps2_sendbyte+0x18c/0x1a0 [ 136.299194] [<ffffff80085c5100>] __ps2_command+0xa8/0x3e8 [ 136.299196] [<ffffff80085c548c>] ps2_command+0x4c/0x78 [ 136.299200] [<ffffff80085d1d6c>] thinking_detect+0x8c/0x108 [ 136.299203] [<ffffff80085d2658>] psmouse_extensions+0x238/0x448 [ 136.299205] [<ffffff80085d2984>] psmouse_switch_protocol+0x11c/0x1a0 [ 136.299208] [<ffffff80085d365c>] psmouse_connect+0x284/0x300 [ 136.299211] [<ffffff80085c47c0>] serio_driver_probe+0x40/0x60 [ 136.299215] [<ffffff80085263b0>] driver_probe_device+0xd0/0x2e8 [ 136.299217] [<ffffff800852667c>] __driver_attach+0xb4/0xb8 [ 136.299220] [<ffffff8008524234>] bus_for_each_dev+0x5c/0xa8 [ 136.299226] [<ffffff8008525d10>] driver_attach+0x30/0x40 [ 136.299228] [<ffffff80085c4404>] serio_handle_event+0xe4/0x230 [ 136.299242] [<ffffff80080d764c>] process_one_work+0x1dc/0x4c8 [ 136.299244] [<ffffff80080d7a64>] worker_thread+0x12c/0x4b0 [ 136.299247] [<ffffff80080de54c>] kthread+0xfc/0x100 [ 136.299251] [<ffffff8008084e90>] ret_from_fork+0x10/0x40 [ 136.299296] No response from PS2 device? What this might indicate is that the kernel didn't think it got the ACK in time, and so abandoned the PS/2 command which was in flight, going around the loop and starting on the next one. Looking at the structure of the KMI interrupt handler and psmouse_interrupt which I think it ultimately calls, it looks like if the interrupt comes in late, it will still read the byte and clear out the interrupt, marking that the device is no longer waiting for an ACK. If the driver has already moved on and doesn't care that it got an ack though, it might have already err-ed out like before. So I guess in conclusion it still looks like a timing thing, rather than (necessarily) an interrupt not getting through thing. Please let me know if there's another way to interpret this, and any comment/advice is welcome. Gabe _______________________________________________ gem5-dev mailing list [email protected] http://m5sim.org/mailman/listinfo/gem5-dev
