tests/bench-arithmetic: Arithmetic operation benchmark#9738
Closed
jnohlgard wants to merge 4 commits intoRIOT-OS:masterfrom
Closed
tests/bench-arithmetic: Arithmetic operation benchmark#9738jnohlgard wants to merge 4 commits intoRIOT-OS:masterfrom
jnohlgard wants to merge 4 commits intoRIOT-OS:masterfrom
Conversation
jnohlgard
added
Area: tests
Member
Author
|
Some interesting observations from the benchmark output:
|
Member
|
16-Bit MSP430 on Zolertia z1: |
Member
|
Unfortunately, I'm not able to build this test for avr8 boards (in Docker). The process just stucks. @kYc0o could you give it a try and paste the output here? |
Contributor
|
Just tested and I think we will deal with the same problem in other boards: 2018-08-21 13:11:52,085 - INFO # main(): This is RIOT! (Version: 2018.10-devel-399-g59835-snake.local-HEAD)
2018-08-21 13:11:52,086 - INFO # Arithmetic benchmark
2018-08-21 13:11:52,096 - INFO # Init timer
2018-08-21 13:11:52,109 - INFO # TIM_REF_DEV: 0
2018-08-21 13:11:52,135 - INFO # TIM_REF_FREQ: 1000000
2018-08-21 13:11:52,162 - INFO # Error initializing timer!Timers in arduino-mega2560 cannot be initialised at 1MHz. For xtimer we use e.g. 250KHz. |
Contributor
|
These are the results at 250KHz: 2018-08-21 13:15:14,340 - INFO # main(): This is RIOT! (Version: 2018.10-devel-399-g59835-snake.local-HEAD)
2018-08-21 13:15:14,344 - INFO # Arithmetic benchmark
2018-08-21 13:15:14,356 - INFO # Init timer
2018-08-21 13:15:14,376 - INFO # TIM_REF_DEV: 0
2018-08-21 13:15:14,395 - INFO # TIM_REF_FREQ: 250000
2018-08-21 13:15:14,395 - INFO #
2018-08-21 13:15:14,397 - INFO #
2018-08-21 13:15:14,491 - INFO # Time in 1/250000 seconds for applying operator op to 128 blocks of size 128 (16384 values)
2018-08-21 13:15:14,492 - INFO #
2018-08-21 13:15:14,532 - INFO # type, op: var cconst rconst
2018-08-21 13:15:14,688 - INFO # Warning! spurious timer interrupt
2018-08-21 13:15:16,093 - INFO # uint8_t, =: 3128 2622 2624
2018-08-21 13:15:17,633 - INFO # uint8_t, +=: 4652 4160 4160
2018-08-21 13:15:19,177 - INFO # uint8_t, -=: 4652 4160 4144
2018-08-21 13:15:20,733 - INFO # uint8_t, *=: 5414 4908 4908
2018-08-21 13:15:22,445 - INFO # uint8_t, /=: 25226 4906 24972
2018-08-21 13:15:24,149 - INFO # uint8_t, <<=: 40006 4652 8208
2018-08-21 13:15:25,890 - INFO # uint8_t, >>=: 48908 4652 9232
2018-08-21 13:15:27,434 - INFO # uint8_t, |=: 4652 4160 4144
2018-08-21 13:15:28,978 - INFO # uint8_t, &=: 4652 4128 4160
2018-08-21 13:15:30,523 - INFO # uint8_t, ^=: 4652 4146 4144
2018-08-21 13:15:32,058 - INFO # uint16_t, =: 4128 3132 3128
2018-08-21 13:15:33,619 - INFO # uint16_t, +=: 6430 5414 5412
2018-08-21 13:15:35,179 - INFO # uint16_t, -=: 6430 5414 5416
2018-08-21 13:15:36,765 - INFO # uint16_t, *=: 8462 7450 7444
2018-08-21 13:15:38,739 - INFO # uint16_t, /=: 57152 6678 56220
2018-08-21 13:15:40,512 - INFO # uint16_t, <<=: 49150 6176 15068
2018-08-21 13:15:42,285 - INFO # uint16_t, >>=: 49150 6176 15068
2018-08-21 13:15:43,846 - INFO # uint16_t, |=: 6430 5414 5416
2018-08-21 13:15:45,407 - INFO # uint16_t, &=: 6430 5414 5412
2018-08-21 13:15:46,971 - INFO # uint16_t, ^=: 6430 5922 5412
2018-08-21 13:15:48,524 - INFO # uint32_t, =: 6176 4152 4144
2018-08-21 13:15:50,125 - INFO # uint32_t, +=: 10496 8462 8462
2018-08-21 13:15:51,727 - INFO # uint32_t, -=: 10496 8462 8462
2018-08-21 13:15:53,570 - INFO # uint32_t, *=: 30048 29040 28532
2018-08-21 13:15:56,347 - INFO # uint32_t, /=: 156088 11402 154168
2018-08-21 13:15:58,427 - INFO # uint32_t, <<=: 70598 37672 38946
2018-08-21 13:16:00,512 - INFO # uint32_t, >>=: 70598 37672 38946
2018-08-21 13:16:02,113 - INFO # uint32_t, |=: 10496 8462 8462
2018-08-21 13:16:03,715 - INFO # uint32_t, &=: 10496 8462 8462
2018-08-21 13:16:05,320 - INFO # uint32_t, ^=: 10496 9478 8462
2018-08-21 13:16:06,910 - INFO # uint64_t, =: 10748 6700 6688
2018-08-21 13:16:08,696 - INFO # uint64_t, +=: 27006 20148 26018
2018-08-21 13:16:10,481 - INFO # uint64_t, -=: 27006 20148 26018
2018-08-21 13:16:13,189 - INFO # uint64_t, *=: 100516 100060 102628
2018-08-21 13:16:15,580 - INFO # uint64_t, /=: 113308 21168 90416
2018-08-21 13:16:17,793 - INFO # uint64_t, <<=: 82912 48592 48598
2018-08-21 13:16:20,017 - INFO # uint64_t, >>=: 84056 49104 49106
2018-08-21 13:16:21,769 - INFO # uint64_t, |=: 24212 20910 20146
2018-08-21 13:16:23,522 - INFO # uint64_t, &=: 24212 20910 20146
2018-08-21 13:16:25,271 - INFO # uint64_t, ^=: 24212 20180 20146 |
Contributor
|
This is for int values: 2018-08-21 13:16:26,799 - INFO # int8_t, =: 3128 2622 2620
2018-08-21 13:16:28,343 - INFO # int8_t, +=: 4652 4160 4144
2018-08-21 13:16:29,887 - INFO # int8_t, -=: 4652 4128 4144
2018-08-21 13:16:31,439 - INFO # int8_t, *=: 5414 4908 4908
2018-08-21 13:16:33,578 - INFO # int8_t, /=: 66966 30308 64224
2018-08-21 13:16:35,273 - INFO # int8_t, <<=: 40006 4398 6272
2018-08-21 13:16:37,006 - INFO # int8_t, >>=: 49416 4160 7192
2018-08-21 13:16:38,550 - INFO # int8_t, |=: 4652 4160 4160
2018-08-21 13:16:40,094 - INFO # int8_t, &=: 4652 4128 4144
2018-08-21 13:16:41,638 - INFO # int8_t, ^=: 4652 4146 4144
2018-08-21 13:16:43,174 - INFO # int16_t, =: 4128 3132 3128
2018-08-21 13:16:44,735 - INFO # int16_t, +=: 6430 5414 5416
2018-08-21 13:16:46,295 - INFO # int16_t, -=: 6430 5414 5416
2018-08-21 13:16:47,880 - INFO # int16_t, *=: 8462 7450 7448
2018-08-21 13:16:50,157 - INFO # int16_t, /=: 66528 64466 64448
2018-08-21 13:16:51,972 - INFO # int16_t, <<=: 49150 6176 25228
2018-08-21 13:16:53,782 - INFO # int16_t, >>=: 49150 5922 25228
2018-08-21 13:16:55,347 - INFO # int16_t, |=: 6430 5414 5412
2018-08-21 13:16:56,907 - INFO # int16_t, &=: 6430 5414 5412
2018-08-21 13:16:58,468 - INFO # int16_t, ^=: 6430 5922 5412
2018-08-21 13:17:00,020 - INFO # int32_t, =: 6176 4152 4144
2018-08-21 13:17:01,622 - INFO # int32_t, +=: 10496 8462 8462
2018-08-21 13:17:03,223 - INFO # int32_t, -=: 10496 8462 8462
2018-08-21 13:17:05,070 - INFO # int32_t, *=: 30056 29040 28532
2018-08-21 13:17:08,548 - INFO # int32_t, /=: 168448 164216 164200
2018-08-21 13:17:10,772 - INFO # int32_t, <<=: 70598 55452 56726
2018-08-21 13:17:12,992 - INFO # int32_t, >>=: 70598 55452 56726
2018-08-21 13:17:14,597 - INFO # int32_t, |=: 10496 8462 8462
2018-08-21 13:17:16,199 - INFO # int32_t, &=: 10496 8462 8462
2018-08-21 13:17:17,804 - INFO # int32_t, ^=: 10496 9478 8462
2018-08-21 13:17:19,396 - INFO # int64_t, =: 10748 6700 6680
2018-08-21 13:17:21,179 - INFO # int64_t, +=: 27006 20148 26018
2018-08-21 13:17:22,965 - INFO # int64_t, -=: 27006 20148 26018
2018-08-21 13:17:25,672 - INFO # int64_t, *=: 100516 100018 102584
2018-08-21 13:17:28,638 - INFO # int64_t, /=: 134274 115730 118300
2018-08-21 13:17:30,809 - INFO # int64_t, <<=: 82916 43264 43264
2018-08-21 13:17:33,000 - INFO # int64_t, >>=: 84560 45296 45296
2018-08-21 13:17:34,749 - INFO # int64_t, |=: 24212 19898 20146
2018-08-21 13:17:36,502 - INFO # int64_t, &=: 24212 20402 20146
2018-08-21 13:17:38,255 - INFO # int64_t, ^=: 24212 20176 20146 |
Contributor
|
And finally, for floats: 2018-08-21 13:17:40,458 - INFO # float, =: 6176 4152 4144
2018-08-21 13:17:43,166 - INFO # float, +=: 37768 51440 50944
2018-08-21 13:17:45,897 - INFO # float, -=: 39376 53200 52692
2018-08-21 13:17:48,576 - INFO # float, *=: 44540 44292 43784
2018-08-21 13:17:52,312 - INFO # float, /=: 132944 132212 131700
2018-08-21 13:17:54,519 - INFO # double, =: 6176 4152 4144
2018-08-21 13:17:57,206 - INFO # double, +=: 37768 48996 48488
2018-08-21 13:17:59,917 - INFO # double, -=: 39376 50728 50216
2018-08-21 13:18:02,592 - INFO # double, *=: 44540 43944 43436
2018-08-21 13:18:06,323 - INFO # double, /=: 132944 131840 131328 |
Member
Author
|
interesting that the 32 bit integer division on atmega is slower than the corresponding 64 bit integer division as well as both 32 bit and 64 bit floating point division. |
Contributor
|
So, how do we proceed with this difference of timer initialisation on atmega? Would you like to support such a feature? |
Member
Author
|
@kYc0o I guess we could special case atmega in the makefile and recompute the numbers to make them comparable between platforms |
Member
Author
|
another approach is to use xtimer for the timing instead of periph_timer directly, but that would add some additional (minor) overhead which could affect the accuracy of the numbers |
Member
Author
|
Updated to avoid division by zero in the shorter integer cases. |
Contributor
|
Oops, maybe too late, but I'd have liked to not use xtimer. I understand the "universality" of it, but still another dependency. Otherwise we would need to know which platforms have a different timer initialisation. |
Contributor
|
To make it work on atmega I needed the following: diff --git a/tests/bench_arithmetic/main.c b/tests/bench_arithmetic/main.c
index 597dd29ba..7a859cd57 100644
--- a/tests/bench_arithmetic/main.c
+++ b/tests/bench_arithmetic/main.c
@@ -237,13 +237,13 @@ int main(void)
puts("Arithmetic benchmark");
puts("Init timer");
- printf("TIM_REF_DEV: %u\n", (unsigned)TIM_REF_DEV);
- printf("TIM_REF_FREQ: %lu\n", (unsigned long)TIM_REF_FREQ);
- int res = timer_init(TIM_REF_DEV, TIM_REF_FREQ, timer_cb, NULL);
+ /*printf("TIM_REF_DEV: %u\n", (unsigned)TIM_REF_DEV);*/
+ printf("TIM_REF_FREQ: %lu\n", (unsigned long)XTIMER_HZ);
+ /*int res = timer_init(TIM_REF_DEV, TIM_REF_FREQ, timer_cb, NULL);
if (res < 0) {
puts("Error initializing timer!");
while(1) {}
- }
+ }*/
uint64_t seed = 12345;
uint32_t variation = 4321;
while (1) {
@@ -252,7 +252,7 @@ int main(void)
uint32_t time_cconst = 0;
uint32_t time_rconst = 0;
printf("\n\nTime in 1/%lu seconds for applying operator op to %u blocks of size %u (%lu values)\n\n",
- TIM_REF_FREQ, TEST_ITERATIONS, TEST_BLOCKSIZE, (unsigned long) TEST_ITERATIONS * TEST_BLOCKSIZE);
+ XTIMER_HZ, TEST_ITERATIONS, TEST_BLOCKSIZE, (unsigned long) TEST_ITERATIONS * TEST_BLOCKSIZE);
printf("%8s, %3s: %7s %7s %7s\n", "type", "op", "var", "cconst", "rconst");
RUN_ALL_TESTS();
++variation; |
Contributor
|
The new results for unsigned integers: 2018-08-28 16:03:12,544 - INFO # main(): This is RIOT! (Version: 2018.10-devel-402-g3b243b-snake.local-HEAD)
2018-08-28 16:03:12,546 - INFO # Arithmetic benchmark
2018-08-28 16:03:12,559 - INFO # Init timer
2018-08-28 16:03:12,580 - INFO # TIM_REF_FREQ: 250000
2018-08-28 16:03:12,582 - INFO #
2018-08-28 16:03:12,584 - INFO #
2018-08-28 16:03:12,678 - INFO # Time in 1/250000 seconds for applying operator op to 128 blocks of size 128 (16384 values)
2018-08-28 16:03:12,678 - INFO #
2018-08-28 16:03:12,719 - INFO # type, op: var cconst rconst
2018-08-28 16:03:14,357 - INFO # uint8_t, =: 12956 10932 10948
2018-08-28 16:03:16,012 - INFO # uint8_t, +=: 19040 17028 17040
2018-08-28 16:03:17,666 - INFO # uint8_t, -=: 19040 17024 17040
2018-08-28 16:03:19,333 - INFO # uint8_t, *=: 22104 20092 20112
2018-08-28 16:03:21,160 - INFO # uint8_t, /=: 101424 20068 100352
2018-08-28 16:03:22,958 - INFO # uint8_t, <<=: 144168 19064 33300
2018-08-28 16:03:24,793 - INFO # uint8_t, >>=: 175680 19048 37360
2018-08-28 16:03:26,448 - INFO # uint8_t, |=: 19068 17024 17024
2018-08-28 16:03:28,106 - INFO # uint8_t, &=: 19056 17020 17028
2018-08-28 16:03:29,761 - INFO # uint8_t, ^=: 19048 17036 17036
2018-08-28 16:03:31,420 - INFO # uint16_t, =: 17024 12988 12964
2018-08-28 16:03:33,108 - INFO # uint16_t, +=: 26168 22100 22088
2018-08-28 16:03:34,795 - INFO # uint16_t, -=: 26168 22100 22108
2018-08-28 16:03:36,507 - INFO # uint16_t, *=: 34300 30252 30208
2018-08-28 16:03:38,604 - INFO # uint16_t, /=: 228104 27172 225316
2018-08-28 16:03:40,501 - INFO # uint16_t, <<=: 191296 25180 60676
2018-08-28 16:03:42,393 - INFO # uint16_t, >>=: 191240 25152 60680
2018-08-28 16:03:44,081 - INFO # uint16_t, |=: 26164 22108 22100
2018-08-28 16:03:45,768 - INFO # uint16_t, &=: 26160 22108 22108
2018-08-28 16:03:47,459 - INFO # uint16_t, ^=: 26172 24116 22096
2018-08-28 16:03:49,086 - INFO # uint32_t, =: 25148 17056 17024
2018-08-28 16:03:50,761 - INFO # uint32_t, +=: 42432 34304 34292
2018-08-28 16:03:52,436 - INFO # uint32_t, -=: 42432 34356 34300
2018-08-28 16:03:54,353 - INFO # uint32_t, *=: 120656 116588 113564
2018-08-28 16:03:57,203 - INFO # uint32_t, /=: 624744 46140 617072
2018-08-28 16:03:59,374 - INFO # uint32_t, <<=: 295304 151184 156256
2018-08-28 16:04:01,541 - INFO # uint32_t, >>=: 295264 151152 156232
2018-08-28 16:04:03,216 - INFO # uint32_t, |=: 42432 34304 34292
2018-08-28 16:04:04,892 - INFO # uint32_t, &=: 42432 34340 34296
2018-08-28 16:04:06,571 - INFO # uint32_t, ^=: 42428 38300 34336
2018-08-28 16:04:08,164 - INFO # uint64_t, =: 43440 27252 27184
2018-08-28 16:04:09,933 - INFO # uint64_t, +=: 107452 81032 86244
2018-08-28 16:04:11,703 - INFO # uint64_t, -=: 107472 81064 86244
2018-08-28 16:04:14,451 - INFO # uint64_t, *=: 421904 412832 415064
2018-08-28 16:04:16,872 - INFO # uint64_t, /=: 473212 85152 366208
2018-08-28 16:04:19,088 - INFO # uint64_t, <<=: 332100 194864 195840
2018-08-28 16:04:21,312 - INFO # uint64_t, >>=: 336708 196904 197860
2018-08-28 16:04:23,069 - INFO # uint64_t, |=: 97296 81044 81072
2018-08-28 16:04:24,821 - INFO # uint64_t, &=: 97296 81032 81040
2018-08-28 16:04:26,575 - INFO # uint64_t, ^=: 97332 81136 81040 |
Contributor
|
Signed integers: 2018-08-28 16:04:28,213 - INFO # int8_t, =: 12952 10928 10944
2018-08-28 16:04:29,868 - INFO # int8_t, +=: 19040 17012 17012
2018-08-28 16:04:31,527 - INFO # int8_t, -=: 19048 17028 17040
2018-08-28 16:04:33,189 - INFO # int8_t, *=: 22112 20088 20072
2018-08-28 16:04:35,438 - INFO # int8_t, /=: 266944 121704 257352
2018-08-28 16:04:37,232 - INFO # int8_t, <<=: 144144 18044 25156
2018-08-28 16:04:39,059 - INFO # int8_t, >>=: 177664 17028 29236
2018-08-28 16:04:40,713 - INFO # int8_t, |=: 19044 17020 17024
2018-08-28 16:04:42,368 - INFO # int8_t, &=: 19064 17024 17056
2018-08-28 16:04:44,027 - INFO # int8_t, ^=: 19044 17036 17036
2018-08-28 16:04:45,686 - INFO # int16_t, =: 17016 12968 12956
2018-08-28 16:04:47,373 - INFO # int16_t, +=: 26172 22096 22084
2018-08-28 16:04:49,061 - INFO # int16_t, -=: 26164 22108 22136
2018-08-28 16:04:50,773 - INFO # int16_t, *=: 34296 30252 30208
2018-08-28 16:04:53,173 - INFO # int16_t, /=: 266604 258116 258124
2018-08-28 16:04:55,106 - INFO # int16_t, <<=: 191264 25148 101348
2018-08-28 16:04:57,040 - INFO # int16_t, >>=: 191288 24152 101348
2018-08-28 16:04:58,727 - INFO # int16_t, |=: 26196 22096 22128
2018-08-28 16:05:00,414 - INFO # int16_t, &=: 26164 22100 22128
2018-08-28 16:05:02,106 - INFO # int16_t, ^=: 26164 24140 22112
2018-08-28 16:05:03,728 - INFO # int32_t, =: 25148 17060 17024
2018-08-28 16:05:05,407 - INFO # int32_t, +=: 42432 34324 34332
2018-08-28 16:05:07,082 - INFO # int32_t, -=: 42432 34304 34296
2018-08-28 16:05:08,999 - INFO # int32_t, *=: 120660 116588 113576
2018-08-28 16:05:12,550 - INFO # int32_t, /=: 673336 657340 657424
2018-08-28 16:05:14,861 - INFO # int32_t, <<=: 295272 222276 227376
2018-08-28 16:05:17,171 - INFO # int32_t, >>=: 295292 222288 227380
2018-08-28 16:05:18,846 - INFO # int32_t, |=: 42436 34320 34296
2018-08-28 16:05:20,525 - INFO # int32_t, &=: 42432 34324 34300
2018-08-28 16:05:22,204 - INFO # int32_t, ^=: 42432 38400 34296
2018-08-28 16:05:23,745 - INFO # int64_t, =: 43440 27256 27180
2018-08-28 16:05:25,469 - INFO # int64_t, +=: 107448 81040 86236
2018-08-28 16:05:27,189 - INFO # int64_t, -=: 107504 81100 86208
2018-08-28 16:05:29,884 - INFO # int64_t, *=: 421976 412800 414848
2018-08-28 16:05:32,841 - INFO # int64_t, /=: 557004 475684 477796
2018-08-28 16:05:34,967 - INFO # int64_t, <<=: 332124 173536 174508
2018-08-28 16:05:37,113 - INFO # int64_t, >>=: 338764 181668 182668
2018-08-28 16:05:38,817 - INFO # int64_t, |=: 97296 77996 81036
2018-08-28 16:05:40,521 - INFO # int64_t, &=: 97332 80032 81032
2018-08-28 16:05:42,225 - INFO # int64_t, ^=: 97296 81132 81032 |
Contributor
|
And floating point: 2018-08-28 16:05:44,433 - INFO # float, =: 25152 17092 17024
2018-08-28 16:05:47,148 - INFO # float, +=: 151556 206336 204332
2018-08-28 16:05:49,880 - INFO # float, -=: 158028 213228 211248
2018-08-28 16:05:52,563 - INFO # float, *=: 178644 177616 175580
2018-08-28 16:05:56,302 - INFO # float, /=: 532328 529360 527336
2018-08-28 16:05:58,510 - INFO # double, =: 25156 17060 17056
2018-08-28 16:06:01,201 - INFO # double, +=: 151520 196468 194432
2018-08-28 16:06:03,917 - INFO # double, -=: 157952 203348 201216
2018-08-28 16:06:06,595 - INFO # double, *=: 178604 176216 174212
2018-08-28 16:06:10,331 - INFO # double, /=: 532288 527860 525880As we can see, the results differ considerably from the usage of the "native" timer. |
Contributor
I see a bunch of tables with lots of data. |
Contributor
|
Ok, let's compare the following table, which was generated using periph_timer initialised at 250KHz: 2018-08-21 13:17:40,458 - INFO # float, =: 6176 4152 4144
2018-08-21 13:17:43,166 - INFO # float, +=: 37768 51440 50944
2018-08-21 13:17:45,897 - INFO # float, -=: 39376 53200 52692
2018-08-21 13:17:48,576 - INFO # float, *=: 44540 44292 43784
2018-08-21 13:17:52,312 - INFO # float, /=: 132944 132212 131700
2018-08-21 13:17:54,519 - INFO # double, =: 6176 4152 4144
2018-08-21 13:17:57,206 - INFO # double, +=: 37768 48996 48488
2018-08-21 13:17:59,917 - INFO # double, -=: 39376 50728 50216
2018-08-21 13:18:02,592 - INFO # double, *=: 44540 43944 43436
2018-08-21 13:18:06,323 - INFO # double, /=: 132944 131840 131328With this one, which is generated using xtimer (which in turn initialises the periph_timer at 250KHz): 2018-08-28 16:05:44,433 - INFO # float, =: 25152 17092 17024
2018-08-28 16:05:47,148 - INFO # float, +=: 151556 206336 204332
2018-08-28 16:05:49,880 - INFO # float, -=: 158028 213228 211248
2018-08-28 16:05:52,563 - INFO # float, *=: 178644 177616 175580
2018-08-28 16:05:56,302 - INFO # float, /=: 532328 529360 527336
2018-08-28 16:05:58,510 - INFO # double, =: 25156 17060 17056
2018-08-28 16:06:01,201 - INFO # double, +=: 151520 196468 194432
2018-08-28 16:06:03,917 - INFO # double, -=: 157952 203348 201216
2018-08-28 16:06:06,595 - INFO # double, *=: 178604 176216 174212
2018-08-28 16:06:10,331 - INFO # double, /=: 532288 527860 525880I hope we can actually see, that the results from xtimer show that the performance is worse, compared to what periph_timer shows. I think this is due to the overhead added by xtimer, since for AVR is not very well optimised. |
Member
Author
|
Ouch, that is super bad. We are working on improving the xtimer situation though, just not ready yet. |
Contributor
Thanks! Apart from expected factor 4, to me it seems there's a constant overhead of ~500. It amounts to less than 1%, so IMO using xtimer is not too bad here. |
Contributor
Well, more like a jitter of ~500. Indeed not as constant as we'd like. Does it look as bad on faster platforms? |
Contributor
|
On samr21-xpro, with xtimer: 2018-08-28 21:51:43,429 - INFO # float, =: 4224 3968 3968
2018-08-28 21:51:44,879 - INFO # float, +=: 50048 48512 47488
2018-08-28 21:51:46,349 - INFO # float, -=: 64256 51328 50646
2018-08-28 21:51:47,874 - INFO # float, *=: 73472 74368 73728
2018-08-28 21:51:49,694 - INFO # float, /=: 170749 171904 171136
2018-08-28 21:51:51,171 - INFO # double, =: 5248 4992 4992
2018-08-28 21:51:52,861 - INFO # double, +=: 75008 75776 75776
2018-08-28 21:51:54,593 - INFO # double, -=: 97920 85376 85376
2018-08-28 21:51:56,532 - INFO # double, *=: 158336 158592 158592
2018-08-28 21:51:59,011 - INFO # double, /=: 338816 336640 336640With periph_timer (very strange numbers): 2018-08-28 21:55:07,620 - INFO # float, =: 4224 4294905600 3840
2018-08-28 21:55:09,069 - INFO # float, +=: 50048 4294753280 4294818816
2018-08-28 21:55:10,537 - INFO # float, -=: 63872 4294886784 4294952704
2018-08-28 21:55:12,061 - INFO # float, *=: 8192 4294910208 8448
2018-08-28 21:55:13,877 - INFO # float, /=: 104768 4294941824 4294876672
2018-08-28 21:55:15,354 - INFO # double, =: 5248 4864 4864
2018-08-28 21:55:17,041 - INFO # double, +=: 75392 76032 75392
2018-08-28 21:55:18,771 - INFO # double, -=: 4294934144 19456 4294920960
2018-08-28 21:55:20,710 - INFO # double, *=: 4294929280 27776 4294928896
2018-08-28 21:55:23,185 - INFO # double, /=: 4294912896 74112 8192 |
Member
Author
|
It's probably the 16 bit timer being picked for the samr21-xpro. The roll over will yield negative numbers in the timing. |
Contributor
|
Interestingly, I have opposite results with the Z1 (msp430). I think we're facing overflows on both timers. Z1 with xtimer: 2018-08-28 22:33:49,154 - INFO # float, =: 29408 33440 4294865600
2018-08-28 22:34:30,923 - INFO # float, +=: 43200 4294832384 4294893824
2018-08-28 22:35:12,938 - INFO # float, -=: 4294947424 4294885216 4294946688
2018-08-28 22:35:58,087 - INFO # float, *=: 4294878848 108480 4294744048
2018-08-28 22:36:39,418 - INFO # float, /=: 48832 4294942112 36288
2018-08-28 22:37:14,882 - INFO # double, =: 29408 4294869664 4294865600
2018-08-28 22:37:55,348 - INFO # double, +=: 43200 79328 9728
2018-08-28 22:38:36,061 - INFO # double, -=: 4294881888 263232 193664
2018-08-28 22:39:21,211 - INFO # double, *=: 4294944256 4294944000 234832
2018-08-28 22:40:02,550 - INFO # double, /=: 4294885056 4294944192 4294940160Z1 with periph_timer: 2018-08-28 22:09:31,110 - INFO # float, =: 28784 32816 28736
2018-08-28 22:10:12,874 - INFO # float, +=: 1287760 2485904 2481856
2018-08-28 22:10:54,883 - INFO # float, -=: 1421296 2538736 2534656
2018-08-28 22:11:40,025 - INFO # float, *=: 3187616 3188032 3184000
2018-08-28 22:12:21,348 - INFO # float, /=: 1948768 1940272 1936256
2018-08-28 22:12:56,804 - INFO # double, =: 28784 32816 28736
2018-08-28 22:13:37,262 - INFO # double, +=: 1287760 1848176 1844096
2018-08-28 22:14:17,964 - INFO # double, -=: 1421296 1901008 1896928
2018-08-28 22:15:03,108 - INFO # double, *=: 3187616 3187392 3183328
2018-08-28 22:15:44,436 - INFO # double, /=: 1948768 1942352 1938272 |
Contributor
|
And finally, on the fastest platform I have, frdm-k64f. With xtimer: 2018-08-28 22:48:20,243 - INFO # float, =: 2272 2547 2432
2018-08-28 22:48:20,377 - INFO # float, +=: 20915 9536 9504
2018-08-28 22:48:20,514 - INFO # float, -=: 22829 9874 9882
2018-08-28 22:48:20,646 - INFO # float, *=: 12345 12621 12608
2018-08-28 22:48:20,875 - INFO # float, /=: 43240 45668 44832
2018-08-28 22:48:21,014 - INFO # double, =: 3610 2547 2816
2018-08-28 22:48:21,246 - INFO # double, +=: 34874 32668 33460
2018-08-28 22:48:21,483 - INFO # double, -=: 39680 33472 33459
2018-08-28 22:48:21,690 - INFO # double, *=: 25651 24979 26585
2018-08-28 22:48:22,352 - INFO # double, /=: 177280 177330 176512and with periph_timer: 2018-08-28 22:49:21,292 - INFO # float, =: 2241 2535 2560
2018-08-28 22:49:21,425 - INFO # float, +=: 21216 9523 9504
2018-08-28 22:49:21,562 - INFO # float, -=: 24448 9760 9785
2018-08-28 22:49:21,690 - INFO # float, *=: 12301 12570 12570
2018-08-28 22:49:21,919 - INFO # float, /=: 45619 44834 45625
2018-08-28 22:49:22,063 - INFO # double, =: 3584 2535 2777
2018-08-28 22:49:22,297 - INFO # double, +=: 35155 31821 31808
2018-08-28 22:49:22,534 - INFO # double, -=: 37517 31815 32610
2018-08-28 22:49:22,743 - INFO # double, *=: 24820 24954 24128
2018-08-28 22:49:23,411 - INFO # double, /=: 178112 177306 177280On which we can appreciate almost no difference. |
Member
Author
|
@kYc0o it would be interesting to see the results from bench_timers on z1, both for periph_timer and for xtimer |
Contributor
|
@gebart I'm trying but just discovered that msp430 devices have only one timer implemented, thus the bench_timers test cannot be run (it needs 2 timers). |
Member
Author
|
@kYc0o a limited test of periph_timer should be possible with USE_REFERENCE set to 0 |
Contributor
|
Maybe it makes sense to move the timing (and tick conversion) out of the inner loop? |
Member
Author
|
Then the filler function will be included in the timing. It is actually the slowest part of the test on certain combinations of parameters, so it would ruin the benchmark results. |
Contributor
|
@gebart with 2018-08-30 18:58:25,074 - INFO # RIOT MSP430 hardware initialization complete.
2018-08-30 18:58:25,076 - INFO # random: NO SEED AVAILABLE!
2018-08-30 18:58:25,088 - INFO # main(): This is RIOT! (Version: 2018.10-devel-621-g8ada7a-snake.local)
2018-08-30 18:58:25,088 - INFO #
2018-08-30 18:58:25,089 - INFO # Statistical benchmark for timers
2018-08-30 18:58:25,095 - INFO # Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
2018-08-30 18:58:25,096 - INFO # TEST_MIN = 16
2018-08-30 18:58:25,100 - INFO # TEST_MAX = 128
2018-08-30 18:58:25,102 - INFO # TEST_MIN_REL = 0
2018-08-30 18:58:25,103 - INFO # TEST_MAX_REL = 112
2018-08-30 18:58:25,136 - INFO # TEST_NUM = 113
2018-08-30 18:58:25,145 - INFO # log2(TEST_NUM - 1) = 6
2018-08-30 18:58:25,147 - INFO # state vector elements per variant = 7
2018-08-30 18:58:25,148 - INFO # number of variants = 8
2018-08-30 18:58:25,149 - INFO # sizeof(state) = 32 bytes
2018-08-30 18:58:25,151 - INFO # state vector total memory usage = 1792 bytes
2018-08-30 18:58:25,155 - INFO # TIM_TEST_DEV = 0, TIM_TEST_FREQ = 1000000, TIM_TEST_CHAN = 0
2018-08-30 18:58:25,156 - INFO # TIM_REF_DEV = 0, TIM_REF_FREQ = 1000000
2018-08-30 18:58:25,157 - INFO # USE_REFERENCE = 0
2018-08-30 18:58:25,157 - INFO # TEST_PRINT_INTERVAL_TICKS = 30000000
2018-08-30 18:58:25,159 - INFO # Expected error variance due to truncation in tick conversion: 0
2018-08-30 18:58:25,160 - INFO # Calibrating spin delay...
2018-08-30 18:58:25,160 - INFO # spin_max = 20
2018-08-30 18:58:25,161 - INFO # Estimating benchmark overhead...
2018-08-30 18:58:25,802 - INFO # overhead_target = 24 (s2 = 0)
2018-08-30 18:58:25,806 - INFO # overhead_read = 24 (s2 = 0)
2018-08-30 18:58:25,807 - INFO # exp_mask = 00000007
2018-08-30 18:58:25,808 - INFO # max interval = 255
2018-08-30 19:04:52,276 - INFO # Elapsed time:
2018-08-30 19:04:52,278 - INFO # Reference: 0
2018-08-30 19:04:52,279 - INFO # Timer under test: 0
2018-08-30 19:04:52,280 - INFO # ------------- BEGIN STATISTICS --------------
2018-08-30 19:04:52,281 - INFO # ===== Reference timer statistics =====
2018-08-30 19:04:52,303 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2018-08-30 19:04:52,307 - INFO # Target error (actual trigger time - expected trigger time), in reference timer ticks
2018-08-30 19:04:52,308 - INFO # positive: timer under test is late, negative: timer under test is early
2018-08-30 19:04:52,309 - INFO # === timer_set running ===
2018-08-30 19:04:52,311 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:52,313 - INFO # 0 - 1: 438 -2527 337 -6 -5 -5 0
2018-08-30 19:04:52,322 - INFO # 2 - 3: 470 -2700 349 -6 -5 -5 0
2018-08-30 19:04:52,331 - INFO # 4 - 7: 471 -2710 354 -6 -5 -5 0
2018-08-30 19:04:52,342 - INFO # 8 - 15: 460 1262 19333 -6 11 2 42 <=== SIC!
2018-08-30 19:04:52,354 - INFO # 16 - 31: 441 1538 33823 -6 20 3 76 <=== SIC!
2018-08-30 19:04:52,365 - INFO # 32 - 63: 443 671 23418 -6 16 1 52 <=== SIC!
2018-08-30 19:04:52,376 - INFO # 64 - 127: 356 -2044 264 -6 -5 -5 0
2018-08-30 19:04:52,402 - INFO # TOTAL 3079 -6510 122572 -6 20 -2 39 <=== SIC!
2018-08-30 19:04:52,403 - INFO # === timer_set resched ===
2018-08-30 19:04:52,404 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:52,414 - INFO # 0 - 1: 459 -1590 1092315 -6 1040 -3 2384 <=== SIC!
2018-08-30 19:04:52,423 - INFO # 2 - 3: 484 -2779 358 -6 -5 -5 0
2018-08-30 19:04:52,435 - INFO # 4 - 7: 466 -1510 1393886 -6 1176 -3 2997 <=== SIC!
2018-08-30 19:04:52,446 - INFO # 8 - 15: 478 1473 19374 -6 11 3 40 <=== SIC!
2018-08-30 19:04:52,457 - INFO # 16 - 31: 496 1464 36897 -6 20 2 74 <=== SIC!
2018-08-30 19:04:52,469 - INFO # 32 - 63: 433 689 22999 -6 16 1 53 <=== SIC!
2018-08-30 19:04:52,480 - INFO # 64 - 127: 326 -1874 244 -6 -5 -5 0
2018-08-30 19:04:52,507 - INFO # TOTAL 3142 -4127 2602547 -6 1176 -1 828 <=== SIC!
2018-08-30 19:04:52,508 - INFO # === timer_set stopped ===
2018-08-30 19:04:52,510 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:52,516 - INFO # 0 - 1: 439 -5817 110 -14 -13 -13 0 <=== SIC!
2018-08-30 19:04:52,527 - INFO # 2 - 3: 458 -5954 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:52,536 - INFO # 4 - 7: 474 -18 5379 -13 3 0 11
2018-08-30 19:04:52,546 - INFO # 8 - 15: 472 -2503 2682 -9 -1 -5 5
2018-08-30 19:04:52,558 - INFO # 16 - 31: 439 -94 40523 -13 12 0 92 <=== SIC!
2018-08-30 19:04:52,569 - INFO # 32 - 63: 459 -4261 10853 -13 2 -9 23 <=== SIC!
2018-08-30 19:04:52,581 - INFO # 64 - 127: 360 -4680 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:52,607 - INFO # TOTAL 3101 -23327 160985 -14 12 -7 51 <=== SIC!
2018-08-30 19:04:52,608 - INFO # === timer_set stopped, resched ===
2018-08-30 19:04:52,609 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:52,618 - INFO # 0 - 1: 428 -5667 102 -14 -13 -13 0 <=== SIC!
2018-08-30 19:04:52,629 - INFO # 2 - 3: 493 -6409 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:52,638 - INFO # 4 - 7: 434 -118 5984 -13 3 0 13
2018-08-30 19:04:52,648 - INFO # 8 - 15: 471 -2434 2718 -9 -1 -5 5
2018-08-30 19:04:52,660 - INFO # 16 - 31: 463 1225 1188521 -13 1073 2 2572 <=== SIC!
2018-08-30 19:04:52,672 - INFO # 32 - 63: 466 -4400 10994 -13 2 -9 23 <=== SIC!
2018-08-30 19:04:52,684 - INFO # 64 - 127: 339 -4407 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:52,710 - INFO # TOTAL 3094 -22210 1321348 -14 1073 -7 427 <=== SIC!
2018-08-30 19:04:52,711 - INFO # === timer_set_absolute running ===
2018-08-30 19:04:52,713 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:52,720 - INFO # 16 - 17: 441 -504 262 -2 0 -1 0
2018-08-30 19:04:52,730 - INFO # 18 - 19: 457 -1426 275 -4 -2 -3 0
2018-08-30 19:04:52,739 - INFO # 20 - 23: 433 -2651 654 -8 -4 -6 1
2018-08-30 19:04:52,752 - INFO # 24 - 31: 438 309 57778 -11 15 0 132 <=== SIC!
2018-08-30 19:04:52,763 - INFO # 32 - 47: 440 1306 10043 -5 11 2 22 <=== SIC!
2018-08-30 19:04:52,773 - INFO # 48 - 79: 436 -4468 1026 -11 -5 -10 2
2018-08-30 19:04:52,785 - INFO # 80 - 143: 337 -3672 301 -11 -10 -10 0
2018-08-30 19:04:52,810 - INFO # TOTAL 2982 -11106 141721 -11 15 -3 47 <=== SIC!
2018-08-30 19:04:52,811 - INFO # === timer_set_absolute resched ===
2018-08-30 19:04:52,813 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:52,819 - INFO # 16 - 17: 469 -556 243 -2 0 -1 0
2018-08-30 19:04:52,829 - INFO # 18 - 19: 432 -1339 238 -4 -2 -3 0
2018-08-30 19:04:52,839 - INFO # 20 - 23: 473 -2918 670 -8 -4 -6 1
2018-08-30 19:04:52,852 - INFO # 24 - 31: 468 -142 60657 -11 15 0 129 <=== SIC!
2018-08-30 19:04:52,863 - INFO # 32 - 47: 418 1395 8908 -5 11 3 21 <=== SIC!
2018-08-30 19:04:52,873 - INFO # 48 - 79: 498 -5153 1133 -11 -5 -10 2
2018-08-30 19:04:52,885 - INFO # 80 - 143: 332 -3610 277 -11 -10 -10 0
2018-08-30 19:04:52,910 - INFO # TOTAL 3090 -12323 149053 -11 15 -3 48 <=== SIC!
2018-08-30 19:04:52,911 - INFO # === timer_set_absolute stopped ===
2018-08-30 19:04:52,913 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:52,920 - INFO # 16 - 17: 463 -4674 226 -11 -9 -10 0
2018-08-30 19:04:52,931 - INFO # 18 - 19: 480 -5848 257 -13 -11 -12 0 <=== SIC!
2018-08-30 19:04:52,943 - INFO # 20 - 23: 474 10 68988 -13 12 0 145 <=== SIC!
2018-08-30 19:04:52,953 - INFO # 24 - 31: 444 2726 2488 2 10 6 5
2018-08-30 19:04:52,965 - INFO # 32 - 47: 475 -2735 9317 -13 2 -5 19 <=== SIC!
2018-08-30 19:04:52,977 - INFO # 48 - 79: 398 -5174 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:52,988 - INFO # 80 - 143: 351 -4563 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:53,014 - INFO # TOTAL 3085 -20258 233256 -13 12 -6 75 <=== SIC!
2018-08-30 19:04:53,016 - INFO # === timer_set_absolute stopped, resched ===
2018-08-30 19:04:53,018 - INFO # interval count sum sum_sq min max mean variance
2018-08-30 19:04:53,024 - INFO # 16 - 17: 447 -4513 213 -11 -9 -10 0
2018-08-30 19:04:53,036 - INFO # 18 - 19: 479 -5806 268 -13 -11 -12 0 <=== SIC!
2018-08-30 19:04:53,048 - INFO # 20 - 23: 443 78 64416 -13 12 0 145 <=== SIC!
2018-08-30 19:04:53,057 - INFO # 24 - 31: 473 2998 2586 2 10 6 5
2018-08-30 19:04:53,069 - INFO # 32 - 47: 468 -2758 10471 -13 2 -5 22 <=== SIC!
2018-08-30 19:04:53,080 - INFO # 48 - 79: 482 -6266 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:53,093 - INFO # 80 - 143: 345 -4485 0 -13 -13 -13 0 <=== SIC!
2018-08-30 19:04:53,112 - INFO # TOTAL 3137 -20752 239785 -13 12 -6 76 <=== SIC!
2018-08-30 19:04:53,114 - INFO # ===== introspective statistics =====
2018-08-30 19:04:53,141 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2018-08-30 19:04:53,144 - INFO # self-referencing error (TUT time elapsed - expected TUT interval), in timer under test ticks
2018-08-30 19:04:53,146 - INFO # positive: timer target handling is slow, negative: TUT is dropping ticks or triggering callback early
2018-08-30 19:04:53,148 - INFO # function count sum sum_sq min max mean variance
2018-08-30 19:04:53,148 - INFO #
2018-08-30 19:04:53,157 - INFO # timer_set 12416 -91545 4274990 -16 1172 -7 344 <=== SIC!
2018-08-30 19:04:53,170 - INFO # running 3079 -18657 137153 -10 16 -6 44 <=== SIC!
2018-08-30 19:04:53,182 - INFO # resched 3142 -16548 2613736 -10 1172 -5 832 <=== SIC!
2018-08-30 19:04:53,195 - INFO # stopped 3101 -28751 161139 -16 11 -9 51 <=== SIC!
2018-08-30 19:04:53,208 - INFO # stopped, resched 3094 -27589 1329624 -16 1071 -8 429 <=== SIC!
2018-08-30 19:04:53,209 - INFO #
2018-08-30 19:04:53,222 - INFO # timer_set_absolute 12294 -97637 817838 -15 11 -7 66 <=== SIC!
2018-08-30 19:04:53,235 - INFO # running 2982 -22348 145752 -15 11 -7 48 <=== SIC!
2018-08-30 19:04:53,247 - INFO # resched 3090 -23948 149831 -15 11 -7 48 <=== SIC!
2018-08-30 19:04:53,261 - INFO # stopped 3085 -25369 232980 -15 11 -8 75 <=== SIC!
2018-08-30 19:04:53,274 - INFO # stopped, resched 3137 -25972 237934 -15 11 -8 75 <=== SIC!
2018-08-30 19:04:53,275 - INFO # -------------- END STATISTICS --------------- |
Contributor
|
I just found this PR: Some observations on the observations:
Division is don in SW in M0. See https://github.com/gcc-mirror/gcc/blob/master/libgcc/config/arm/lib1funcs.S
3 to five times as slow, according to http://infocenter.arm.com/help/index.jsp?topic=/com.arm.doc.ddi0439b/CHDDIGAC.html, plus the time you need to load more registers. In m0 you may have a hard time benchmarking because manufacturers have a choice of multiplier implementation, from 1 to 32 cycles.
This is expected. The 32 bit register is the smallest unit in the ARM CPU. I usually dislike this kind of synthetic benchmarks because they can be misleading:
|
|
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If you want me to ignore this issue, please mark it with the "State: don't stale" label. Thank you for your contributions. |
stale
bot
added
the
State: stale
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
10 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Contribution description
Adds an arithmetic operations benchmark for the most common basic data types and operations. This can be used as a guideline for when it might be useful to try to optimize slow code, and what to look for in that code.
Issues/PRs references
spawned from #9283 but entirely free standing.