search

LDMX-Software / ldmx-sw

The Light Dark Matter eXperiment simulation and reconstruction framework.
https://ldmx-software.github.io
GNU General Public License v3.0
21 stars 19 forks source link

Tracking timing changes in log diffs #1402

Open tvami opened 3 weeks ago

tvami commented 3 weeks ago

Is your feature request related to a problem? Please describe. Logs always fail now because of the character count different

<  [ SeedFinderProcessor ] 1 : AVG Time/Event: 0.0986296 ms
  ---
  >  [ SeedFinderProcessor ] 1 : AVG Time/Event: 0.0978154 ms
  244c244
  <  [ SeedRecoil ] 1 : AVG Time/Event: 0.136037 ms
  ---
  >  [ SeedRecoil ] 1 : AVG Time/Event: 0.133573 ms
  256c256
  <  [ Tagger_TrackFinder ] 1 : AVG Time/Event: 0.395085 ms
  ---
  >  [ Tagger_TrackFinder ] 1 : AVG Time/Event: 0.39516 ms
  258,263c258,263
  <  [ Tagger_TrackFinder ] 1 : setup       Avg Time/Event = 0.00228943 ms
  <  [ Tagger_TrackFinder ] 1 : hits        Avg Time/Event = 0.0433836 ms
  <  [ Tagger_TrackFinder ] 1 : seeds       Avg Time/Event = 0.00342895 ms
  <  [ Tagger_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.00407709 ms
  <  [ Tagger_TrackFinder ] 1 : ckf_run     Avg Time/Event = 0.000160371 ms
  <  [ Tagger_TrackFinder ] 1 : result_loop Avg Time/Event = 0.339842 ms
  ---
  >  [ Tagger_TrackFinder ] 1 : setup       Avg Time/Event = 0.00216297 ms
  >  [ Tagger_TrackFinder ] 1 : hits        Avg Time/Event = 0.044[55](https://github.com/LDMX-Software/ldmx-sw/actions/runs/10496314488/job/29077738861?pr=1401#step:6:58)07 ms
  >  [ Tagger_TrackFinder ] 1 : seeds       Avg Time/Event = 0.00345044 ms
  >  [ Tagger_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.00419966 ms
  >  [ Tagger_TrackFinder ] 1 : ckf_run     Avg Time/Event = 0.0001725 ms
  >  [ Tagger_TrackFinder ] 1 : result_loop Avg Time/Event = 0.33878 ms
  265c265
  <  [ Recoil_TrackFinder ] 1 : AVG Time/Event: 0.298821 ms
  ---
  >  [ Recoil_TrackFinder ] 1 : AVG Time/Event: 0.308164 ms
  267,272c267,272
  <  [ Recoil_TrackFinder ] 1 : setup       Avg Time/Event = 0.000543621 ms
  <  [ Recoil_TrackFinder ] 1 : hits        Avg Time/Event = 0.042665 ms
  <  [ Recoil_TrackFinder ] 1 : seeds       Avg Time/Event = 0.00260774 ms
  <  [ Recoil_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.00199831 ms
  <  [ Recoil_TrackFinder ] 1 : ckf_run     Avg Time/Event = 0.000136034 ms
  <  [ Recoil_TrackFinder ] 1 : result_loop Avg Time/Event = 0.250555 ms
  ---
  >  [ Recoil_TrackFinder ] 1 : setup       Avg Time/Event = 0.000690733 ms
  >  [ Recoil_TrackFinder ] 1 : hits        Avg Time/Event = 0.0449752 ms
  >  [ Recoil_TrackFinder ] 1 : seeds       Avg Time/Event = 0.00296358 ms
  >  [ Recoil_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.00209514 ms
  >  [ Recoil_TrackFinder ] 1 : ckf_run     Avg Time/Event = 0.000153931 ms
  >  [ Recoil_TrackFinder ] 1 : result_loop Avg Time/Event = 0.2[56](https://github.com/LDMX-Software/ldmx-sw/actions/runs/10496314488/job/29077738861?pr=1401#step:6:59)973 ms

Describe the solution you'd like

We should round these numbers to a fixed number of digits. But also it's interesting that rerunning ACTS on the same events takes different times.

Describe alternatives you've considered

Figure out why those numbers are different, is that expected @bloodyyugo

Additional context

PR test here https://github.com/LDMX-Software/ldmx-sw/actions/runs/10496314488/job/29077738861?pr=1401

tomeichlersmith commented 3 weeks ago

I mean, the times are ranging from tenths to hundreds of microseconds so I feel like the time changing is just a product of the performance of the runner that we happen to land on.

tvami commented 3 weeks ago

Sure that makes sense, let's just round them and get the diffs to zero with that solution!

tvami commented 5 days ago

It seems this wasnt enough and we need to go more course https://github.com/LDMX-Software/ldmx-sw/actions/runs/10746102897/job/29806990784#step:6:22

<  [ SeedFinderProcessor ] 1 : AVG Time/Event: 0.0980 ms
  ---
  >  [ SeedFinderProcessor ] 1 : AVG Time/Event: 0.0931 ms
  10284c10284
  <  [ SeedRecoil ] 1 : AVG Time/Event: 0.1364 ms
  ---
  >  [ SeedRecoil ] 1 : AVG Time/Event: 0.1349 ms
  10296c10296
  <  [ Tagger_TrackFinder ] 1 : AVG Time/Event: 0.3939 ms
  ---
  >  [ Tagger_TrackFinder ] 1 : AVG Time/Event: 0.3829 ms
  10298,10301c10298,10301
  <  [ Tagger_TrackFinder ] 1 : setup       Avg Time/Event = 0.0021 ms
  <  [ Tagger_TrackFinder ] 1 : hits        Avg Time/Event = 0.0441 ms
  <  [ Tagger_TrackFinder ] 1 : seeds       Avg Time/Event = 0.0032 ms
  <  [ Tagger_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.0043 ms
  ---
  >  [ Tagger_TrackFinder ] 1 : setup       Avg Time/Event = 0.0020 ms
  >  [ Tagger_TrackFinder ] 1 : hits        Avg Time/Event = 0.0434 ms
  >  [ Tagger_TrackFinder ] 1 : seeds       Avg Time/Event = 0.0030 ms
  >  [ Tagger_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.0041 ms
  10303c10303
  <  [ Tagger_TrackFinder ] 1 : result_loop Avg Time/Event = 0.3382 ms
  ---
  >  [ Tagger_TrackFinder ] 1 : result_loop Avg Time/Event = 0.3283 ms
  10305c10305
  <  [ Recoil_TrackFinder ] 1 : AVG Time/Event: 0.3056 ms
  ---
  >  [ Recoil_TrackFinder ] 1 : AVG Time/Event: 0.3026 ms
  10308c10308
  <  [ Recoil_TrackFinder ] 1 : hits        Avg Time/Event = 0.0451 ms
  ---
  >  [ Recoil_TrackFinder ] 1 : hits        Avg Time/Event = 0.0437 ms
  10310,10312c10310,10312
  <  [ Recoil_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.0020 ms
  <  [ Recoil_TrackFinder ] 1 : ckf_run     Avg Time/Event = 0.0001 ms
  <  [ Recoil_TrackFinder ] 1 : result_loop Avg Time/Event = 0.[25](https://github.com/LDMX-Software/ldmx-sw/actions/runs/10746102897/job/29806990784#step:6:28)49 ms
  ---
  >  [ Recoil_TrackFinder ] 1 : cf_setup    Avg Time/Event = 0.0021 ms
  >  [ Recoil_TrackFinder ] 1 : ckf_run     Avg Time/Event = 0.0002 ms
  >  [ Recoil_TrackFinder ] 1 : result_loop Avg Time/Event = 0.25[31](https://github.com/LDMX-Software/ldmx-sw/actions/runs/10746102897/job/29806990784#step:6:34) ms