> -----Original Message-----
> From: Marc Kleine-Budde <mkl@xxxxxxxxxxxxxx>
> Sent: 2019年11月12日 16:38
> To: Joakim Zhang <qiangqing.zhang@xxxxxxx>; sean@xxxxxxxxxx;
> linux-can@xxxxxxxxxxxxxxx
> Subject: Re: Wake up issue about Flexcan driver in v5.4 kernel
>
> 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.
Thanks Marc, I will learn how to use trace_printk() later as it cannot work at my side now. However, the same output without printk(), so the latencies here has no effect.
> BTW: You might want to use the cangen option "-Ii", so that cangen will not
> generate random, but incrementing CAN-ids.
Okay.
> > 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?
ip link set can0 up type can bitrate 1000000
> 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?
Of course, with pleasure.
Best Regards,
Joakim Zhang
> 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 |
