microsoft / microsoft/lepton_jpeg_rust

Wrong CPU time metric

Open
#76 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug
Dominant language
Rust
Stars
182
Forks
17
Avg merge
19h 46m
Merged PRs (30d)
1

Description

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 0swaps

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by tracing the CPU-time reporting in the lepton_jpeg_util output, especially the lepton_jpeg_util::structs::lepton_format logging shown in the report. Reproduce the single-core and multi-core commands with perf or time, then determine which reported totals disagree; done means the application’s CPU-time metrics match the established measurements.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
performance
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.