| Message ID | 1489774651-30170-6-git-send-email-akinobu.mita@gmail.com (mailing list archive) |
|---|---|
| State | Accepted |
| Commit | ea9936f32435699907807aaac87f993482208578 |
| Headers | show |
Hi! Trying my luck here. I'm playing with the spi-s3c64xx.c driver and the spi-loopback-test and sometimes I see that I get the following error: ```elapsed time x ns is shorter than minimum estimated time y ns``` What's strange to me is that if I ignore the return value of spi_test_check_elapsed_time(), the test passes, there's no transfer mismatch and what we expect we actually get at RX. What kind of errors does the spi_test_check_elapsed_time() check want to discover? Under what conditions the test->elapsed_time is inaccurate? Thanks! Find below an example of a test that I run: / # modprobe spi-loopback-test simulate_only=0 loopback=1 loop_req=1 check_ranges=1 dump_messages=3 delay_ms=300 run_only_test=14 [ 6748.888603] spi-loopback-test spi13.0: feedback delay set to default (0) [ 6748.888773] spi-loopback-test spi13.0: Executing spi-loopback-tests [ 6748.888962] spi-loopback-test spi13.0: with iteration values: len = 512, tx_off = 0, rx_off = 0 [ 6748.889164] spi-loopback-test spi13.0: spi_msg@00000000cf23e9a1 [ 6748.889295] spi-loopback-test spi13.0: frame_length: 0 [ 6748.889417] spi-loopback-test spi13.0: actual_length: 0 [ 6748.889538] spi-loopback-test spi13.0: spi_transfer@0000000010068ced [ 6748.889680] spi-loopback-test spi13.0: len: 1 [ 6748.889793] spi-loopback-test spi13.0: tx_buf: 000000009aba786a [ 6748.889959] TX: 00000000: 00 [ 6748.890097] spi-loopback-test spi13.0: rx_buf: 000000000819d83b [ 6748.890343] RX: 00000000: aa [ 6748.890501] spi-loopback-test spi13.0: rx_buf filled with aa starts at offset: 0 [ 6748.890788] spi-loopback-test spi13.0: spi_transfer@00000000cd58625b [ 6748.891045] spi-loopback-test spi13.0: len: 512 [ 6748.891247] spi-loopback-test spi13.0: tx_buf: 0000000062a28e45 [ 6748.891494] TX: 00000000: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 [ 6748.891786] TX: 00000010: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 [ 6748.892079] TX: 00000020: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 [ 6748.892371] TX: 00000030: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 [ 6748.892664] TX: 00000040: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 [ 6748.892957] TX: 00000050: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 [ 6748.893249] TX: 00000060: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 [ 6748.893542] TX: 00000070: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 [ 6748.893835] TX: 00000080: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 [ 6748.894128] TX: 00000090: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 [ 6748.894420] TX: 000000a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 [ 6748.894719] TX: 000000b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 [ 6748.895006] TX: 000000c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 [ 6748.895298] TX: 000000d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 [ 6748.895591] TX: 000000e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 [ 6748.895883] TX: 000000f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa fb fc fd fe ff 00 [ 6748.896176] TX: 00000100: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 [ 6748.896469] TX: 00000110: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 [ 6748.896762] TX: 00000120: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 [ 6748.897059] TX: 00000130: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 [ 6748.897347] TX: 00000140: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 [ 6748.897639] TX: 00000150: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 [ 6748.897932] TX: 00000160: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 [ 6748.898225] TX: 00000170: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 [ 6748.898525] TX: 00000180: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 [ 6748.898811] TX: 00000190: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 [ 6748.899103] TX: 000001a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 [ 6748.899396] TX: 000001b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 [ 6748.899688] TX: 000001c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 [ 6748.899981] TX: 000001d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 [ 6748.900274] TX: 000001e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 [ 6748.900567] TX: 000001f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa fb fc fd fe ff 00 [ 6748.900860] spi-loopback-test spi13.0: rx_buf: 00000000df223723 [ 6748.901105] RX: 00000000: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.901398] RX: 00000010: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.901696] RX: 00000020: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.901983] RX: 00000030: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.902276] RX: 00000040: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.902575] RX: 00000050: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.902861] RX: 00000060: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.903154] RX: 00000070: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.903447] RX: 00000080: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.903739] RX: 00000090: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.904036] RX: 000000a0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.904325] RX: 000000b0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.904618] RX: 000000c0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.904910] RX: 000000d0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.905203] RX: 000000e0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.905496] RX: 000000f0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.905788] RX: 00000100: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.906081] RX: 00000110: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.906373] RX: 00000120: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.906675] RX: 00000130: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.906985] RX: 00000140: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.907251] RX: 00000150: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.907544] RX: 00000160: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.907836] RX: 00000170: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.908129] RX: 00000180: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.908422] RX: 00000190: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.908714] RX: 000001a0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.909007] RX: 000001b0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.909300] RX: 000001c0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.909592] RX: 000001d0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.909885] RX: 000001e0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.910177] RX: 000001f0: aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa [ 6748.910482] spi-loopback-test spi13.0: rx_buf filled with aa starts at offset: 0 [ 6748.910773] spi-loopback-test spi13.0: spi_transfer@00000000774992f1 [ 6748.911035] spi-loopback-test spi13.0: len: 1 [ 6748.911225] spi-loopback-test spi13.0: tx_buf: 00000000401e03ed [ 6748.911472] TX: 00000000: 01 [ 6748.911614] spi-loopback-test spi13.0: rx_buf: 0000000010f7e3e4 [ 6748.911860] RX: 00000000: aa [ 6748.912004] spi-loopback-test spi13.0: rx_buf filled with aa starts at offset: 0 [ 6748.913400] spi-loopback-test spi13.0: elapsed time 532837 ns is shorter than minimum estimated time 82240000 ns [ 6748.913611] spi-loopback-test spi13.0: spi_msg@00000000cf23e9a1 [ 6748.913741] spi-loopback-test spi13.0: frame_length: 514 [ 6748.913863] spi-loopback-test spi13.0: actual_length: 514 [ 6748.913985] spi-loopback-test spi13.0: spi_transfer@0000000010068ced [ 6748.914222] spi-loopback-test spi13.0: len: 1 [ 6748.914418] spi-loopback-test spi13.0: tx_buf: 000000009aba786a [ 6748.914673] TX: 00000000: 00 [ 6748.914808] spi-loopback-test spi13.0: rx_buf: 000000000819d83b [ 6748.915053] RX: 00000000: 00 [ 6748.915197] spi-loopback-test spi13.0: spi_transfer@00000000cd58625b [ 6748.915453] spi-loopback-test spi13.0: len: 512 [ 6748.915656] spi-loopback-test spi13.0: tx_buf: 0000000062a28e45 [ 6748.915901] TX: 00000000: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 [ 6748.916194] TX: 00000010: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 [ 6748.916492] TX: 00000020: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 [ 6748.916780] TX: 00000030: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 [ 6748.917072] TX: 00000040: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 [ 6748.917365] TX: 00000050: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 [ 6748.917658] TX: 00000060: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 [ 6748.917950] TX: 00000070: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 [ 6748.918243] TX: 00000080: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 [ 6748.918539] TX: 00000090: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 [ 6748.918833] TX: 000000a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 [ 6748.919121] TX: 000000b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 [ 6748.919414] TX: 000000c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 [ 6748.919706] TX: 000000d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 [ 6748.919999] TX: 000000e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 [ 6748.920292] TX: 000000f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa fb fc fd fe ff 00 [ 6748.920584] TX: 00000100: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 [ 6748.920877] TX: 00000110: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 [ 6748.921174] TX: 00000120: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 [ 6748.921463] TX: 00000130: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 [ 6748.921755] TX: 00000140: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 [ 6748.922048] TX: 00000150: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 [ 6748.922341] TX: 00000160: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 [ 6748.922636] TX: 00000170: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 [ 6748.922926] TX: 00000180: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 [ 6748.923219] TX: 00000190: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 [ 6748.923516] TX: 000001a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 [ 6748.923804] TX: 000001b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 [ 6748.924097] TX: 000001c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 [ 6748.924390] TX: 000001d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 [ 6748.924682] TX: 000001e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 [ 6748.924975] TX: 000001f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa fb fc fd fe ff 00 [ 6748.925268] spi-loopback-test spi13.0: rx_buf: 00000000df223723 [ 6748.925514] RX: 00000000: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 [ 6748.925811] RX: 00000010: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 [ 6748.926099] RX: 00000020: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 [ 6748.926392] RX: 00000030: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 [ 6748.926687] RX: 00000040: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 [ 6748.926977] RX: 00000050: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 [ 6748.927270] RX: 00000060: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 [ 6748.927562] RX: 00000070: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 [ 6748.927855] RX: 00000080: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 [ 6748.928153] RX: 00000090: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 [ 6748.928440] RX: 000000a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 [ 6748.928733] RX: 000000b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 [ 6748.929026] RX: 000000c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 [ 6748.929318] RX: 000000d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 [ 6748.929611] RX: 000000e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 [ 6748.929904] RX: 000000f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa fb fc fd fe ff 00 [ 6748.930197] RX: 00000100: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10 [ 6748.930493] RX: 00000110: 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 [ 6748.930782] RX: 00000120: 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 [ 6748.931074] RX: 00000130: 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 [ 6748.931367] RX: 00000140: 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 [ 6748.931660] RX: 00000150: 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 [ 6748.931953] RX: 00000160: 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 [ 6748.932245] RX: 00000170: 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f 80 [ 6748.932538] RX: 00000180: 81 82 83 84 85 86 87 88 89 8a 8b 8c 8d 8e 8f 90 [ 6748.932836] RX: 00000190: 91 92 93 94 95 96 97 98 99 9a 9b 9c 9d 9e 9f a0 [ 6748.933123] RX: 000001a0: a1 a2 a3 a4 a5 a6 a7 a8 a9 aa ab ac ad ae af b0 [ 6748.933416] RX: 000001b0: b1 b2 b3 b4 b5 b6 b7 b8 b9 ba bb bc bd be bf c0 [ 6748.933709] RX: 000001c0: c1 c2 c3 c4 c5 c6 c7 c8 c9 ca cb cc cd ce cf d0 [ 6748.934001] RX: 000001d0: d1 d2 d3 d4 d5 d6 d7 d8 d9 da db dc dd de df e0 [ 6748.934294] RX: 000001e0: e1 e2 e3 e4 e5 e6 e7 e8 e9 ea eb ec ed ee ef f0 [ 6748.934589] RX: 000001f0: f1 f2 f3 f4 f5 f6 f7 f8 f9 fa fb fc fd fe ff 00 [ 6748.934880] spi-loopback-test spi13.0: spi_transfer@00000000774992f1 [ 6748.935140] spi-loopback-test spi13.0: len: 1 [ 6748.935332] spi-loopback-test spi13.0: tx_buf: 00000000401e03ed [ 6748.935578] TX: 00000000: 01 [ 6748.935721] spi-loopback-test spi13.0: rx_buf: 0000000010f7e3e4 [ 6748.935967] RX: 00000000: 01 [ 6749.236147] spi-loopback-test spi13.0: Finished spi-loopback-tests with return: 0 On 3/17/17 18:17, Akinobu Mita wrote: > This adds checks whether the elapsed time is longer than the minimam > estimated time. The estimated time is calculated with the total > transfer length per clock rate and optional spi_transfer.delay_usecs. > > Cc: Martin Sperl <kernel-TqfNSX0MhmxHKSADF0wUEw@public.gmane.org> > Cc: Mark Brown <broonie-DgEjT+Ai2ygdnm+yROfE0A@public.gmane.org> > Signed-off-by: Akinobu Mita <akinobu.mita-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> > --- > drivers/spi/spi-loopback-test.c | 38 ++++++++++++++++++++++++++++++++++++++ > drivers/spi/spi-test.h | 2 ++ > 2 files changed, 40 insertions(+) > > diff --git a/drivers/spi/spi-loopback-test.c b/drivers/spi/spi-loopback-test.c > index 6df6ddd..66e8cfd0 100644 > --- a/drivers/spi/spi-loopback-test.c > +++ b/drivers/spi/spi-loopback-test.c > @@ -20,6 +20,7 @@ > > #include <linux/delay.h> > #include <linux/kernel.h> > +#include <linux/ktime.h> > #include <linux/list.h> > #include <linux/list_sort.h> > #include <linux/module.h> > @@ -479,6 +480,35 @@ static int spi_check_rx_ranges(struct spi_device *spi, > return ret; > } > > +static int spi_test_check_elapsed_time(struct spi_device *spi, > + struct spi_test *test) > +{ > + int i; > + unsigned long long estimated_time = 0; > + unsigned long long delay_usecs = 0; > + > + for (i = 0; i < test->transfer_count; i++) { > + struct spi_transfer *xfer = test->transfers + i; > + unsigned long long nbits = BITS_PER_BYTE * xfer->len; > + > + delay_usecs += xfer->delay_usecs; > + if (!xfer->speed_hz) > + continue; > + estimated_time += div_u64(nbits * NSEC_PER_SEC, xfer->speed_hz); > + } > + > + estimated_time += delay_usecs * NSEC_PER_USEC; > + if (test->elapsed_time < estimated_time) { > + dev_err(&spi->dev, > + "elapsed time %lld ns is shorter than minimam estimated time %lld ns\n", > + test->elapsed_time, estimated_time); > + > + return -EINVAL; > + } > + > + return 0; > +} > + > static int spi_test_check_loopback_result(struct spi_device *spi, > struct spi_message *msg, > void *tx, void *rx) > @@ -817,12 +847,16 @@ int spi_test_execute_msg(struct spi_device *spi, struct spi_test *test, > > /* only if we do not simulate */ > if (!simulate_only) { > + ktime_t start; > + > /* dump the complete message before and after the transfer */ > if (dump_messages == 3) > spi_test_dump_message(spi, msg, true); > > + start = ktime_get(); > /* run spi message */ > ret = spi_sync(spi, msg); > + test->elapsed_time = ktime_to_ns(ktime_sub(ktime_get(), start)); > if (ret == -ETIMEDOUT) { > dev_info(&spi->dev, > "spi-message timed out - reruning...\n"); > @@ -848,6 +882,10 @@ int spi_test_execute_msg(struct spi_device *spi, struct spi_test *test, > > /* run rx-buffer tests */ > ret = spi_test_check_loopback_result(spi, msg, tx, rx); > + if (ret) > + goto exit; > + > + ret = spi_test_check_elapsed_time(spi, test); > } > > /* if requested or on error dump message (including data) */ > diff --git a/drivers/spi/spi-test.h b/drivers/spi/spi-test.h > index 82fff4a..6ed7b89 100644 > --- a/drivers/spi/spi-test.h > +++ b/drivers/spi/spi-test.h > @@ -75,6 +75,7 @@ > * @fill_option: define the way how tx_buf is filled > * @fill_pattern: fill pattern to apply to the tx_buf > * (used in some of the @fill_options) > + * @elapsed_time: elapsed time in nanoseconds > */ > > struct spi_test { > @@ -108,6 +109,7 @@ struct spi_test { > #define FILL_TRANSFER_BYTE_32 11 /* fill with the transfer byte - 32 bit */ > #define FILL_TRANSFER_NUM 16 /* fill with the transfer number */ > u32 fill_pattern; > + unsigned long long elapsed_time; > }; > > /* default implementation for @spi_test.run_test */
On Fri, Jan 12, 2024 at 04:19:10PM +0000, Tudor Ambarus wrote: > I'm playing with the spi-s3c64xx.c driver and the spi-loopback-test and > sometimes I see that I get the following error: > ```elapsed time x ns is shorter than minimum estimated time y ns``` > What's strange to me is that if I ignore the return value of > spi_test_check_elapsed_time(), the test passes, there's no transfer > mismatch and what we expect we actually get at RX. > What kind of errors does the spi_test_check_elapsed_time() check want to > discover? Under what conditions the test->elapsed_time is inaccurate? The test is calculating the expected time based on the intended clock rate for the bus and any delays in the message. This should identify if a driver is either ignoring specified delays or overclocking the bus. > [ 6748.910773] spi-loopback-test spi13.0: spi_transfer@00000000774992f1 > [ 6748.911035] spi-loopback-test spi13.0: len: 1 > [ 6748.911225] spi-loopback-test spi13.0: tx_buf: 00000000401e03ed > [ 6748.911472] TX: 00000000: 01 > [ 6748.911614] spi-loopback-test spi13.0: rx_buf: 0000000010f7e3e4 > [ 6748.911860] RX: 00000000: aa > [ 6748.912004] spi-loopback-test spi13.0: rx_buf filled with aa > starts at offset: 0 > [ 6748.913400] spi-loopback-test spi13.0: elapsed time 532837 ns is > shorter than minimum estimated time 82240000 ns That's a *very* substantial error, it makes me suspect that the hardware might be doing loopback at a stage before it actually clocks the bus and doing something like just connecting the TX and RX FIFOs.
On 1/12/24 18:37, Mark Brown wrote: >> [ 6748.913400] spi-loopback-test spi13.0: elapsed time 532837 ns is >> shorter than minimum estimated time 82240000 ns > That's a *very* substantial error, it makes me suspect that the hardware > might be doing loopback at a stage before it actually clocks the bus and > doing something like just connecting the TX and RX FIFOs. Thanks, Mark! It was a problem on how the clocks were handled, I ended up with a higher frequency than I requested. Cheers, ta
On Thu, Jan 18, 2024 at 08:30:39AM +0000, Tudor Ambarus wrote: > On 1/12/24 18:37, Mark Brown wrote: > >> [ 6748.913400] spi-loopback-test spi13.0: elapsed time 532837 ns is > >> shorter than minimum estimated time 82240000 ns > > That's a *very* substantial error, it makes me suspect that the hardware > > might be doing loopback at a stage before it actually clocks the bus and > > doing something like just connecting the TX and RX FIFOs. > Thanks, Mark! It was a problem on how the clocks were handled, I ended > up with a higher frequency than I requested. Ouch, hopefully that's only affecting loopback mode and not normal operation for everyone.
On 1/18/24 12:42, Mark Brown wrote: > On Thu, Jan 18, 2024 at 08:30:39AM +0000, Tudor Ambarus wrote: >> On 1/12/24 18:37, Mark Brown wrote: > >>>> [ 6748.913400] spi-loopback-test spi13.0: elapsed time 532837 ns is >>>> shorter than minimum estimated time 82240000 ns > >>> That's a *very* substantial error, it makes me suspect that the hardware >>> might be doing loopback at a stage before it actually clocks the bus and >>> doing something like just connecting the TX and RX FIFOs. > >> Thanks, Mark! It was a problem on how the clocks were handled, I ended >> up with a higher frequency than I requested. > > Ouch, hopefully that's only affecting loopback mode and not normal > operation for everyone. It was a problem on the clock driver which is not yet upstream. SPI is fine, in loopback mode at least, that's all I could test for now.
diff --git a/drivers/spi/spi-loopback-test.c b/drivers/spi/spi-loopback-test.c index 6df6ddd..66e8cfd0 100644 --- a/drivers/spi/spi-loopback-test.c +++ b/drivers/spi/spi-loopback-test.c @@ -20,6 +20,7 @@ #include <linux/delay.h> #include <linux/kernel.h> +#include <linux/ktime.h> #include <linux/list.h> #include <linux/list_sort.h> #include <linux/module.h> @@ -479,6 +480,35 @@ static int spi_check_rx_ranges(struct spi_device *spi, return ret; } +static int spi_test_check_elapsed_time(struct spi_device *spi, + struct spi_test *test) +{ + int i; + unsigned long long estimated_time = 0; + unsigned long long delay_usecs = 0; + + for (i = 0; i < test->transfer_count; i++) { + struct spi_transfer *xfer = test->transfers + i; + unsigned long long nbits = BITS_PER_BYTE * xfer->len; + + delay_usecs += xfer->delay_usecs; + if (!xfer->speed_hz) + continue; + estimated_time += div_u64(nbits * NSEC_PER_SEC, xfer->speed_hz); + } + + estimated_time += delay_usecs * NSEC_PER_USEC; + if (test->elapsed_time < estimated_time) { + dev_err(&spi->dev, + "elapsed time %lld ns is shorter than minimam estimated time %lld ns\n", + test->elapsed_time, estimated_time); + + return -EINVAL; + } + + return 0; +} + static int spi_test_check_loopback_result(struct spi_device *spi, struct spi_message *msg, void *tx, void *rx) @@ -817,12 +847,16 @@ int spi_test_execute_msg(struct spi_device *spi, struct spi_test *test, /* only if we do not simulate */ if (!simulate_only) { + ktime_t start; + /* dump the complete message before and after the transfer */ if (dump_messages == 3) spi_test_dump_message(spi, msg, true); + start = ktime_get(); /* run spi message */ ret = spi_sync(spi, msg); + test->elapsed_time = ktime_to_ns(ktime_sub(ktime_get(), start)); if (ret == -ETIMEDOUT) { dev_info(&spi->dev, "spi-message timed out - reruning...\n"); @@ -848,6 +882,10 @@ int spi_test_execute_msg(struct spi_device *spi, struct spi_test *test, /* run rx-buffer tests */ ret = spi_test_check_loopback_result(spi, msg, tx, rx); + if (ret) + goto exit; + + ret = spi_test_check_elapsed_time(spi, test); } /* if requested or on error dump message (including data) */ diff --git a/drivers/spi/spi-test.h b/drivers/spi/spi-test.h index 82fff4a..6ed7b89 100644 --- a/drivers/spi/spi-test.h +++ b/drivers/spi/spi-test.h @@ -75,6 +75,7 @@ * @fill_option: define the way how tx_buf is filled * @fill_pattern: fill pattern to apply to the tx_buf * (used in some of the @fill_options) + * @elapsed_time: elapsed time in nanoseconds */ struct spi_test { @@ -108,6 +109,7 @@ struct spi_test { #define FILL_TRANSFER_BYTE_32 11 /* fill with the transfer byte - 32 bit */ #define FILL_TRANSFER_NUM 16 /* fill with the transfer number */ u32 fill_pattern; + unsigned long long elapsed_time; }; /* default implementation for @spi_test.run_test */
This adds checks whether the elapsed time is longer than the minimam estimated time. The estimated time is calculated with the total transfer length per clock rate and optional spi_transfer.delay_usecs. Cc: Martin Sperl <kernel@martin.sperl.org> Cc: Mark Brown <broonie@kernel.org> Signed-off-by: Akinobu Mita <akinobu.mita@gmail.com> --- drivers/spi/spi-loopback-test.c | 38 ++++++++++++++++++++++++++++++++++++++ drivers/spi/spi-test.h | 2 ++ 2 files changed, 40 insertions(+)