On 11/12/19 8:12 AM, Joakim Zhang wrote:
> I dump some info in wake up case from v5.3.10 with below change:
> printk("\nmailbox_num = %u, timestamp = %u, can_id = %x\n", n, *timestamp, cf->can_id);
Keep in mind, a printk() compared to a trace_printk() will introduce
bigger latencies.
BTW: You might want to use the cangen option "-Ii", so that cangen will
not generate random, but incrementing CAN-ids.
> 1)
> Sender: cangen can0 -vv
> can0 266 [8] F2 2D C6 5F 0E FE DE 38
> can0 71E [8] 8A F0 C5 2F 9F 3C 72 32
> can0 256 [2] 03 4B
> can0 6FC [8] B1 46 D5 40 F6 C4 CC 1D
> can0 21A [2] 60 2C
> can0 594 [2] B1 5A
> can0 162 [2] CB 41
> can0 6B0 [4] CA 64 AB 70
> can0 710 [8] 25 27 2F 11 2F 76 54 17
> can0 50B [8] CE B2 C6 49 61 1F B9 3A
>
> Receiver: candump can0 &
> mailbox_num = 1, timestamp = 4113563648, can_id = 266
> mailbox_num = 2, timestamp = 4105568256, can_id = 71e
> mailbox_num = 3, timestamp = 43646976, can_id = 256
> mailbox_num = 4, timestamp = 276496384, can_id = 6fc
> mailbox_num = 5, timestamp = 509149184, can_id = 21a
> mailbox_num = 6, timestamp = 741605376, can_id = 594
Reading mailboxes 1 to 6 probably means that it took the duration of 6
CAN frames (+ the added overhead of the printk()s) until the IRQ fired
and reached mailbox 6.
However starting with frame 3 the timestamps look good.
> mailbox_num = 1, timestamp = 973406208, can_id = 162
> mailbox_num = 1, timestamp = 1205010432, can_id = 6b0
> mailbox_num = 1, timestamp = 1437138944, can_id = 710
> mailbox_num = 1, timestamp = 1670184960, can_id = 50b
> can0 71E [8] 8A F0 C5 2F 9F 3C 72 32
> can0 266 [8] F2 2D C6 5F 0E FE DE 38
> can0 256 [2] 03 4B
> can0 6FC [8] B1 46 D5 40 F6 C4 CC 1D
> can0 21A [2] 60 2C
> can0 594 [2] B1 5A
> can0 162 [2] CB 41
> can0 6B0 [4] CA 64 AB 70
> can0 710 [8] 25 27 2F 11 2F 76 54 17
> can0 50B [8] CE B2 C6 49 61 1F B9 3A
>
> 2)
> Sender: cangen can0 -g 100 -vv
> can0 343 [4] 13 89 21 5D
> can0 2DF [8] E6 64 C6 25 ED F0 7B 16
> can0 353 [8] 9B 84 9B 21 CA A3 CC 50
> can0 4E2 [8] 63 0E B0 1E 70 0E C2 12
> can0 643 [4] 75 9E 6E 08
> can0 3D1 [5] E9 A6 FE 1D 88
> can0 4E6 [8] A3 02 0E 08 1B F1 32 4F
> can0 6E2 [1] 1B
> can0 026 [8] 08 36 25 73 05 BB F3 4F
> can0 1CD [8] F3 AB 6F 66 20 ED B2 46
> can0 157 [8] EB 90 7F 17 39 0E E7 48
> can0 227 [8] A9 1C A9 5B 6B 78 7D 33
> can0 6D2 [8] A3 E3 01 56 A3 3A AB 3C
> can0 2D4 [8] 2C F5 A4 62 BA C7 6E 7D
> can0 416 [8] D5 B8 A1 4C F8 E2 EF 0A
> can0 6B0 [1] 1E
> can0 620 [6] DC 01 4F 77 ED 1F
> can0 615 [8] 0D 0D 98 68 6C E7 EF 06
> can0 65D [8] A5 F5 D6 4F 85 D0 9B 14
> can0 546 [8] F0 48 19 48 18 C4 DA 53
> can0 56D [3] BC FE 85
> can0 71F [8] FB 57 77 5D 35 AB E6 73
>
> Receiver: candump can0 &
> mailbox_num = 1, timestamp = 1521614848, can_id = 343
> mailbox_num = 2, timestamp = 3618439168, can_id = 2df
> mailbox_num = 3, timestamp = 1590951936, can_id = 353
> mailbox_num = 4, timestamp = 3859611648, can_id = 4e2
> mailbox_num = 5, timestamp = 1833238528, can_id = 643
> mailbox_num = 6, timestamp = 4101767168, can_id = 3d1
> mailbox_num = 7, timestamp = 2076770304, can_id = 4e6
> mailbox_num = 8, timestamp = 50135040, can_id = 6e2
> mailbox_num = 9, timestamp = 2318729216, can_id = 26
> mailbox_num = 10, timestamp = 291897344, can_id = 1cd
> mailbox_num = 11, timestamp = 2559901696, can_id = 157
> mailbox_num = 12, timestamp = 532742144, can_id = 227
> mailbox_num = 1, timestamp = 2801336320, can_id = 6d2
> mailbox_num = 1, timestamp = 776011776, can_id = 2d4
> mailbox_num = 1, timestamp = 3044343808, can_id = 416
> mailbox_num = 1, timestamp = 1016332288, can_id = 6b0
>
> can0 343 [4] 13 89 21 5D
> can0 353 [8] 9B 84 9B 21 CA A3 CC 50
> can0 643 [4] 75 9E 6E 08
> can0 4E6 [8] A3 02 0E 08 1B F1 32 4F
> can0 026 [8] 08 36 25 73 05 BB F3 4F
> can0 157 [8] EB 90 7F 17 39 0E E7 48
> can0 2DF [8] E6 64 C6 25 ED F0 7B 16
> can0 4E2 [8] 63 0E B0 1E 70 0E C2 12
> can0 3D1 [5] E9 A6 FE 1D 88
> can0 6E2 [1] 1B
> can0 1CD [8] F3 AB 6F 66 20 ED B2 46
> can0 227 [8] A9 1C A9 5B 6B 78 7D 33
> can0 6D2 [8] A3 E3 01 56 A3 3A AB 3C
> can0 2D4 [8] 2C F5 A4 62 BA C7 6E 7D
> can0 416 [8] D5 B8 A1 4C F8 E2 EF 0A
> can0 6B0 [1] 1E
>
> I found that not only the wake up frame will out-of-order, frames
> read in one round including wake up frame all could be disordered.
Yes, these timestamps are all over the place. It's due to the "big" gap
of 100ms between the CAN frames. What's the configured bitrate of your bus?
If the timestamp counter is incremented with each bit on the bus
(recheck the data sheet) a 16 bit counter will overflow quite often. At
500 kbit/s it about 2^16 / 500000 = 0.131072ms.
If we cannot patch the silicon to have a wider counter or a counter
pre-scaler :) You could implement a first IRQ after wakeup hack to read
all frames in order without sorting them.
I think we can explain case 2), but I think case 1) is different. Can
you repeat testcase 1) several times and send the output?
Marc
--
Pengutronix e.K. | Marc Kleine-Budde |
Embedded Linux | https://www.pengutronix.de |
Vertretung West/Dortmund | Phone: +49-231-2826-924 |
Amtsgericht Hildesheim, HRA 2686 | Fax: +49-5121-206917-5555 |
Attachment:
signature.asc
Description: OpenPGP digital signature
