Wrong CPU time metric
Melirius opened this issue · 1 comments
Melirius commented
CPU time measurements are definitely wrong. When I limit Lepton to a single core, reported times are typically nearly twice larger then time reported by perf and time, for example
ivan@ivan-5950:~/lepton_jpeg_rust$ sudo rm images/0.lep; sudo perf stat -B -e cache-references,cache-misses,cycles,stalled-cycles-backend,stalled-cycles-frontend,instructions,branch-instructions,branch-misses,ic_fetch_stall.ic_stall_any,l2_cache_misses_from_ic_miss,l2_latency.l2_cycles_waiting_on_fills,faults,migrations taskset -c 10 nice -n -20 target/release/lepton_jpeg_util images/0.jpg images/0.lep
2024-05-13T19:57:57.426Z INFO [lepton_jpeg_util::structs::lepton_format] compressing to Lepton format
2024-05-13T19:57:57.892Z INFO [lepton_jpeg_util::structs::lepton_format] Number of threads: 8
2024-05-13T19:57:59.434Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1541ms of CPU time in 1541ms of wall time
2024-05-13T19:57:59.454Z INFO [lepton_jpeg_util::structs::lepton_format] decompressing to verify contents
2024-05-13T19:58:01.184Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1722ms of CPU time in 1729ms of wall time
2024-05-13T19:58:01.198Z INFO [lepton_jpeg_util] compressed input 22171278, output 17324596 bytes (ratio = 28.0%)
2024-05-13T19:58:01.198Z INFO [lepton_jpeg_util] Total CPU time consumed:7035ms
Performance counter stats for 'taskset -c 10 nice -n -20 target/release/lepton_jpeg_util images/0.jpg images/0.lep':
785 590 057 cache-references (45,30%)
65 972 448 cache-misses # 8,40% of all cache refs (45,46%)
17 302 087 799 cycles (45,63%)
762 732 452 stalled-cycles-backend # 4,41% backend cycles idle (45,74%)
37 246 027 stalled-cycles-frontend # 0,22% frontend cycles idle (45,84%)
43 029 268 863 instructions # 2,49 insn per cycle
# 0,02 stalled cycles per insn (45,78%)
4 572 852 634 branch-instructions (45,57%)
163 246 621 branch-misses # 3,57% of all branches (45,36%)
6 397 381 526 ic_fetch_stall.ic_stall_any (45,25%)
55 026 687 l2_cache_misses_from_ic_miss (45,26%)
1 563 306 107 l2_latency.l2_cycles_waiting_on_fills (45,20%)
136 764 faults
1 migrations
3,816304958 seconds time elapsed
3,527629000 seconds user
0,287969000 seconds sys
ivan@ivan-5950:~/lepton_jpeg_rust$ sudo rm images/0.lep; sudo target/release/lepton_jpeg_util images/0.jpg images/0.lep
2024-05-13T20:00:21.531Z INFO [lepton_jpeg_util::structs::lepton_format] compressing to Lepton format
2024-05-13T20:00:21.986Z INFO [lepton_jpeg_util::structs::lepton_format] Number of threads: 8
2024-05-13T20:00:22.234Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1591ms of CPU time in 246ms of wall time
2024-05-13T20:00:22.260Z INFO [lepton_jpeg_util::structs::lepton_format] decompressing to verify contents
2024-05-13T20:00:22.541Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1819ms of CPU time in 280ms of wall time
2024-05-13T20:00:22.552Z INFO [lepton_jpeg_util] compressed input 22171278, output 17324596 bytes (ratio = 28.0%)
2024-05-13T20:00:22.552Z INFO [lepton_jpeg_util] Total CPU time consumed:4432ms
ivan@ivan-5950:~/lepton_jpeg_rust$ sudo rm images/0.lep; sudo time taskset -c 10 nice -n -20 target/release/lepton_jpeg_util images/0.jpg images/0.lep
2024-05-13T20:02:13.408Z INFO [lepton_jpeg_util::structs::lepton_format] compressing to Lepton format
2024-05-13T20:02:13.860Z INFO [lepton_jpeg_util::structs::lepton_format] Number of threads: 8
2024-05-13T20:02:15.394Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1533ms of CPU time in 1533ms of wall time
2024-05-13T20:02:15.414Z INFO [lepton_jpeg_util::structs::lepton_format] decompressing to verify contents
2024-05-13T20:02:17.121Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1699ms of CPU time in 1706ms of wall time
2024-05-13T20:02:17.135Z INFO [lepton_jpeg_util] compressed input 22171278, output 17324596 bytes (ratio = 28.0%)
2024-05-13T20:02:17.135Z INFO [lepton_jpeg_util] Total CPU time consumed:6960ms
3.54user 0.23system 0:03.77elapsed 99%CPU (0avgtext+0avgdata 348024maxresident)k
0inputs+33840outputs (0major+136789minor)pagefaults 0swaps
ivan@ivan-5950:~/lepton_jpeg_rust$ sudo rm images/0.lep; sudo time target/release/lepton_jpeg_util images/0.jpg images/0.lep
2024-05-13T20:02:44.969Z INFO [lepton_jpeg_util::structs::lepton_format] compressing to Lepton format
2024-05-13T20:02:45.417Z INFO [lepton_jpeg_util::structs::lepton_format] Number of threads: 8
2024-05-13T20:02:45.668Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1595ms of CPU time in 249ms of wall time
2024-05-13T20:02:45.695Z INFO [lepton_jpeg_util::structs::lepton_format] decompressing to verify contents
2024-05-13T20:02:45.984Z INFO [lepton_jpeg_util::structs::lepton_format] worker threads 1910ms of CPU time in 289ms of wall time
2024-05-13T20:02:46.001Z INFO [lepton_jpeg_util] compressed input 22171278, output 17324596 bytes (ratio = 28.0%)
2024-05-13T20:02:46.001Z INFO [lepton_jpeg_util] Total CPU time consumed:4538ms
3.74user 0.31system 0:01.07elapsed 377%CPU (0avgtext+0avgdata 355572maxresident)k
0inputs+33840outputs (0major+181927minor)pagefaults 0swapsRockPolish commented