[Clas12_software] DB initialization and FTCAL
Vardan Gyurjyan
gurjyan at jlab.org
Sun Mar 4 12:23:09 EST 2018
That would have ben something wrong with the data. Now for the current run: RUN 3545 looked reasonable, yet take into account that FT services are not in the chain.
2018-03-04 12:20:09.863: Benchmark results:
2018-03-04 12:20:09.863: READER 3000 events total time = 108.99 s average event time = 36.33 ms
2018-03-04 12:20:09.864: DCHB 3000 events total time = 4131.99 s average event time = 1377.33 ms
2018-03-04 12:20:09.865: DCTB 3000 events total time = 410.18 s average event time = 136.73 ms
2018-03-04 12:20:09.866: FTOF 3000 events total time = 4.88 s average event time = 1.63 ms
2018-03-04 12:20:09.867: CVT 3000 events total time = 61.76 s average event time = 20.59 ms
2018-03-04 12:20:09.867: CTOF 3000 events total time = 3.57 s average event time = 1.19 ms
2018-03-04 12:20:09.868: HTCC 3000 events total time = 0.62 s average event time = 0.21 ms
2018-03-04 12:20:09.869: LTCC 3000 events total time = 0.67 s average event time = 0.22 ms
2018-03-04 12:20:09.869: EC 3000 events total time = 3.72 s average event time = 1.24 ms
2018-03-04 12:20:09.870: EBHB 3000 events total time = 4.92 s average event time = 1.64 ms
2018-03-04 12:20:09.871: EBTB 3000 events total time = 3.69 s average event time = 1.23 ms
2018-03-04 12:20:09.871: WRITER 3000 events total time = 10.14 s average event time = 3.38 ms
2018-03-04 12:20:09.872: TOTAL 3000 events total time = 4745.14 s average event time = 1581.71 ms
-vardan
> On Mar 4, 2018, at 11:48 AM, Francois-Xavier Girod <fxgirod at jlab.org> wrote:
>
> Dear Vardan
>
> This is actually nearly a factor 2 worse than what I saw on the test I ran using run 3512 which is also at 50 nA
>
>
> =========================================
> CLARA FE/DPE
> =========================================
> Name = 129.57.137.148%7720_java
> Session = test_master
> Date = 2018-03-02 21:12:52
> Version = 4.3
> Lang = Java
> Pool size = 16
>
> Proxy Host = 129.57.137.148
> Proxy Port = 7720
> =========================================
> ****************************************
> * CLARA Orchestrator *
> ****************************************
> - Front-end = 129.57.137.148%7720_java
> - Start time = 2018-03-02 21:12:53
> - Threads = 64
>
> - Input directory = /u/scratch/fxgirod/test
> - Output directory = /u/scratch/fxgirod/test
> - Number of files = 1
> ****************************************
> 2018-03-02 21:12:53.664: Waiting for local node...
> 2018-03-02 21:12:53.815: Start processing on 129.57.137.148...
> 2018-03-02 21:12:53.815: Searching services in 129.57.137.148...
> 2018-03-02 21:12:53.829: Deploying services in 129.57.137.148...
> 2018-03-02 21:12:54: started container = 129.57.137.148%7720_java:fxgirod
> SVT geometry constants loaded ? true
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:DataManager pool_size = 1
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:HipoToHipoWriter pool_size = 1
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:HipoToHipoReader pool_size = 1
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:CVT pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:FTCAL pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:CTOF pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:RICH pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:LTCC pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:EC pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:CND pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:FTOF pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:FTHODO pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:HTCC pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:FTEB pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:DCTB pool_size = 64
> 2018-03-02 21:12:54: started service = 129.57.137.148%7720_java:fxgirod:DCHB pool_size = 64
> 2018-03-02 21:12:55: started service = 129.57.137.148%7720_java:fxgirod:EBHB pool_size = 64
> 2018-03-02 21:12:55: started service = 129.57.137.148%7720_java:fxgirod:EBTB pool_size = 64
> 2018-03-02 21:12:56.346: All services deployed on 129.57.137.148
> 2018-03-02 21:12:56.600: Configuring services on 129.57.137.148...
>
> 2018-03-02 21:13:00.580: All services configured on 129.57.137.148
> 2018-03-02 21:13:00.643: Opening file clas_003512.evio.1400.hipo on 129.57.137.148
> INFO HipoToHipoReader - request to open file /u/scratch/fxgirod/test/clas_003512.evio.1400.hipo
> [READER] ----> opening current file : /u/scratch/fxgirod/test/clas_003512.evio.1400.hipo
> [READER] ---> open successful, size : 539515644
> 27560 56 0
> [READER] ---> initializing dictionary........
> [READER] ---> user header record event count 116
> [READER] ---> total number of schema loaded 116
> INFO HipoToHipoReader - opened file /u/scratch/fxgirod/test/clas_003512.evio.1400.hipo
> INFO HipoToHipoReader - config time: 270 [ms]
> INFO HipoToHipoReader - execute request count
> INFO HipoToHipoReader - execute request order
> INFO HipoToHipoWriter - request to open file /u/scratch/fxgirod/test/out_clas_003512.evio.1400.hipo
>
>
>
> [DB] ---> database disconnect : success
> [DB] ---> database disconnect : success
> SUCCESSFULLY LOADED BMT CONSTANTS....
> use inter + 269.76000000000005use inter + 318.04use inter + 318.04use inter + 352.322018-03-02 21:13:31.440: Processed 500 events total time = 30.41 s average event time = 60.82 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.04use inter + 269.760000000000052018-03-02 21:13:45.209: Processed 1000 events total time = 44.18 s average event time = 44.18 ms
> use inter + 318.04use inter + 318.04use inter + 352.322018-03-02 21:13:58.912: Processed 1500 events total time = 57.88 s average event time = 38.59 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:14:13.406: Processed 2000 events total time = 72.38 s average event time = 36.19 ms
> use inter + 269.76000000000005use inter + 352.322018-03-02 21:14:26.675: Processed 2500 events total time = 85.65 s average event time = 34.26 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 318.042018-03-02 21:14:38.229: Processed 3000 events total time = 97.20 s average event time = 32.40 ms
> 2018-03-02 21:14:50.903: Processed 3500 events total time = 109.87 s average event time = 31.39 ms
> use inter + 269.76000000000005use inter + 352.322018-03-02 21:15:05.791: Processed 4000 events total time = 124.76 s average event time = 31.19 ms
> 2018-03-02 21:15:20.424: Processed 4500 events total time = 139.39 s average event time = 30.98 ms
> use inter + 318.04use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:15:33.820: Processed 5000 events total time = 152.79 s average event time = 30.56 ms
> use inter + 318.04use inter + 352.32use inter + 269.760000000000052018-03-02 21:15:47.139: Processed 5500 events total time = 166.11 s average event time = 30.20 ms
> use inter + 318.04use inter + 352.32use inter + 318.04use inter + 318.04use inter + 318.04use inter + 352.32use inter + 318.04use inter + 269.760000000000052018-03-02 21:16:00.312: Processed 6000 events total time = 179.28 s average event time = 29.88 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.042018-03-02 21:16:13.515: Processed 6500 events total time = 192.49 s average event time = 29.61 ms
> use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 318.04use inter + 352.322018-03-02 21:16:27.022: Processed 7000 events total time = 205.99 s average event time = 29.43 ms
> use inter + 269.76000000000005use inter + 318.042018-03-02 21:16:39.543: Processed 7500 events total time = 218.51 s average event time = 29.14 ms
> use inter + 269.76000000000005use inter + 352.322018-03-02 21:16:51.072: Processed 8000 events total time = 230.04 s average event time = 28.76 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.322018-03-02 21:17:03.814: Processed 8500 events total time = 242.78 s average event time = 28.56 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 318.04use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:17:17.577: Processed 9000 events total time = 256.55 s average event time = 28.51 ms
> use inter + 269.76000000000005use inter + 352.32use inter + 269.760000000000052018-03-02 21:17:30.274: Processed 9500 events total time = 269.24 s average event time = 28.34 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.042018-03-02 21:17:42.429: Processed 10000 events total time = 281.40 s average event time = 28.14 ms
> use inter + 269.760000000000052018-03-02 21:17:55.133: Processed 10500 events total time = 294.10 s average event time = 28.01 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 352.322018-03-02 21:18:08.901: Processed 11000 events total time = 307.87 s average event time = 27.99 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.322018-03-02 21:18:21.396: Processed 11500 events total time = 320.37 s average event time = 27.86 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:18:33.474: Processed 12000 events total time = 332.44 s average event time = 27.70 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.04use inter + 352.322018-03-02 21:18:45.094: Processed 12500 events total time = 344.06 s average event time = 27.53 ms
> use inter + 318.04use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 352.322018-03-02 21:18:56.773: Processed 13000 events total time = 355.74 s average event time = 27.36 ms
> use inter + 318.042018-03-02 21:19:09.349: Processed 13500 events total time = 368.32 s average event time = 27.28 ms
> 2018-03-02 21:19:21.930: Processed 14000 events total time = 380.90 s average event time = 27.21 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.32use inter + 318.042018-03-02 21:19:36.230: Processed 14500 events total time = 395.20 s average event time = 27.26 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 318.042018-03-02 21:19:50.210: Processed 15000 events total time = 409.18 s average event time = 27.28 ms
> use inter + 318.04use inter + 318.042018-03-02 21:20:05.036: Processed 15500 events total time = 424.01 s average event time = 27.36 ms
> use inter + 352.322018-03-02 21:20:17.436: Processed 16000 events total time = 436.41 s average event time = 27.28 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.322018-03-02 21:20:31.100: Processed 16500 events total time = 450.07 s average event time = 27.28 ms
> use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.32use inter + 269.760000000000052018-03-02 21:20:44.218: Processed 17000 events total time = 463.19 s average event time = 27.25 ms
> use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.322018-03-02 21:20:55.711: Processed 17500 events total time = 474.68 s average event time = 27.12 ms
> use inter + 318.04use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:21:07.694: Processed 18000 events total time = 486.66 s average event time = 27.04 ms
> use inter + 318.042018-03-02 21:21:21.944: Processed 18500 events total time = 500.91 s average event time = 27.08 ms
> use inter + 318.04use inter + 352.322018-03-02 21:21:34.504: Processed 19000 events total time = 513.47 s average event time = 27.02 ms
> use inter + 318.042018-03-02 21:21:49.420: Processed 19500 events total time = 528.39 s average event time = 27.10 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 352.32use inter + 318.042018-03-02 21:22:03.183: Processed 20000 events total time = 542.15 s average event time = 27.11 ms
> use inter + 269.76000000000005use inter + 352.32use inter + 269.760000000000052018-03-02 21:22:16.387: Processed 20500 events total time = 555.36 s average event time = 27.09 ms
> use inter + 269.760000000000052018-03-02 21:22:30.818: Processed 21000 events total time = 569.79 s average event time = 27.13 ms
> 2018-03-02 21:22:44.309: Processed 21500 events total time = 583.28 s average event time = 27.13 ms
> 2018-03-02 21:22:57.366: Processed 22000 events total time = 596.34 s average event time = 27.11 ms
> 2018-03-02 21:23:10.478: Processed 22500 events total time = 609.45 s average event time = 27.09 ms
> 2018-03-02 21:23:24.153: Processed 23000 events total time = 623.12 s average event time = 27.09 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:23:37.129: Processed 23500 events total time = 636.10 s average event time = 27.07 ms
> use inter + 269.760000000000052018-03-02 21:23:51.383: Processed 24000 events total time = 650.35 s average event time = 27.10 ms
> use inter + 318.042018-03-02 21:24:04.093: Processed 24500 events total time = 663.06 s average event time = 27.06 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:24:18.119: Processed 25000 events total time = 677.09 s average event time = 27.08 ms
> use inter + 269.76000000000005use inter + 318.042018-03-02 21:24:32.225: Processed 25500 events total time = 691.20 s average event time = 27.11 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.04use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.32use inter + 352.322018-03-02 21:24:43.824: Processed 26000 events total time = 702.79 s average event time = 27.03 ms
> use inter + 318.04use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.04use inter + 352.322018-03-02 21:24:56.687: Processed 26500 events total time = 715.66 s average event time = 27.01 ms
> use inter + 318.04use inter + 352.32use inter + 269.760000000000052018-03-02 21:25:09.024: Processed 27000 events total time = 727.99 s average event time = 26.96 ms
> 2018-03-02 21:25:21.438: Processed 27500 events total time = 740.41 s average event time = 26.92 ms
> use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.32use inter + 318.04use inter + 318.042018-03-02 21:25:34.962: Processed 28000 events total time = 753.93 s average event time = 26.93 ms
> use inter + 269.760000000000052018-03-02 21:25:48.217: Processed 28500 events total time = 767.19 s average event time = 26.92 ms
> use inter + 269.76000000000005use inter + 318.042018-03-02 21:26:01.276: Processed 29000 events total time = 780.25 s average event time = 26.91 ms
> use inter + 318.04use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:26:14.394: Processed 29500 events total time = 793.36 s average event time = 26.89 ms
> use inter + 318.042018-03-02 21:26:28.426: Processed 30000 events total time = 807.40 s average event time = 26.91 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.042018-03-02 21:26:41.592: Processed 30500 events total time = 820.56 s average event time = 26.90 ms
> 2018-03-02 21:26:53.929: Processed 31000 events total time = 832.90 s average event time = 26.87 ms
> 2018-03-02 21:27:06.239: Processed 31500 events total time = 845.21 s average event time = 26.83 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 318.04use inter - -395.962018-03-02 21:27:19.741: Processed 32000 events total time = 858.71 s average event time = 26.83 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.04use inter + 318.042018-03-02 21:27:32.963: Processed 32500 events total time = 871.93 s average event time = 26.83 ms
> 2018-03-02 21:27:46.651: Processed 33000 events total time = 885.62 s average event time = 26.84 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 352.32use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:27:59.573: Processed 33500 events total time = 898.54 s average event time = 26.82 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 318.042018-03-02 21:28:13.008: Processed 34000 events total time = 911.98 s average event time = 26.82 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 269.760000000000052018-03-02 21:28:26.017: Processed 34500 events total time = 924.99 s average event time = 26.81 ms
> use inter + 318.04use inter + 318.04use inter + 352.322018-03-02 21:28:39.411: Processed 35000 events total time = 938.38 s average event time = 26.81 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:28:52.591: Processed 35500 events total time = 951.56 s average event time = 26.80 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.322018-03-02 21:29:06.558: Processed 36000 events total time = 965.53 s average event time = 26.82 ms
> use inter + 318.042018-03-02 21:29:19.985: Processed 36500 events total time = 978.96 s average event time = 26.82 ms
> use inter + 318.04use inter + 352.32use inter + 269.760000000000052018-03-02 21:29:33.479: Processed 37000 events total time = 992.45 s average event time = 26.82 ms
> use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.04use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 318.04use inter + 352.322018-03-02 21:29:47.129: Processed 37500 events total time = 1006.10 s average event time = 26.83 ms
> use inter + 318.04use inter + 352.32use inter + 318.04use inter + 352.322018-03-02 21:30:00.770: Processed 38000 events total time = 1019.74 s average event time = 26.84 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 269.76000000000005use inter + 352.32use inter + 352.32use inter + 318.042018-03-02 21:30:14.252: Processed 38500 events total time = 1033.22 s average event time = 26.84 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 269.76000000000005use inter - -395.96use inter + 318.04use inter + 269.760000000000052018-03-02 21:30:29.052: Processed 39000 events total time = 1048.02 s average event time = 26.87 ms
> use inter + 269.760000000000052018-03-02 21:30:43.108: Processed 39500 events total time = 1062.08 s average event time = 26.89 ms
> 2018-03-02 21:30:57.906: Processed 40000 events total time = 1076.88 s average event time = 26.92 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 318.042018-03-02 21:31:12.089: Processed 40500 events total time = 1091.06 s average event time = 26.94 ms
> use inter + 269.76000000000005use inter + 318.04use inter + 269.760000000000052018-03-02 21:31:25.074: Processed 41000 events total time = 1104.04 s average event time = 26.93 ms
> use inter + 352.32use inter + 318.04use inter + 352.32use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:31:37.535: Processed 41500 events total time = 1116.51 s average event time = 26.90 ms
> use inter + 269.76000000000005use inter + 269.760000000000052018-03-02 21:31:51.455: Processed 42000 events total time = 1130.43 s average event time = 26.91 ms
> use inter + 318.04use inter + 352.322018-03-02 21:32:03.770: Processed 42500 events total time = 1142.74 s average event time = 26.89 ms
> use inter + 318.042018-03-02 21:32:17.768: Processed 43000 events total time = 1156.74 s average event time = 26.90 ms
> use inter + 352.32use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.76000000000005use inter + 269.76000000000005use inter + 318.042018-03-02 21:32:31.091: Processed 43500 events total time = 1170.06 s average event time = 26.90 ms
> 2018-03-02 21:32:31.340: All events read from clas_003512.evio.1400.hipo on 129.57.137.148. Waiting for output events...
> 2018-03-02 21:33:05.791: Finished file clas_003512.evio.1400.hipo on 129.57.137.148. Average event time = 27.65 ms
> INFO HipoToHipoReader - request to close file /u/scratch/fxgirod/test/clas_003512.evio.1400.hipo
> INFO HipoToHipoReader - closed file /u/scratch/fxgirod/test/clas_003512.evio.1400.hipo
> INFO HipoToHipoReader - config time: 0 [ms]
> INFO HipoToHipoWriter - request to close file /u/scratch/fxgirod/test/out_clas_003512.evio.1400.hipo
> INFO HipoToHipoWriter - closed file /u/scratch/fxgirod/test/out_clas_003512.evio.1400.hipo
> INFO HipoToHipoWriter - config time: 107 [ms]
> 2018-03-02 21:33:06.338: Benchmark results:
> 2018-03-02 21:33:06.339: READER 43579 events total time = 6.15 s average event time = 0.14 ms
> 2018-03-02 21:33:06.339: FTCAL 43579 events total time = 18.42 s average event time = 0.42 ms
> 2018-03-02 21:33:06.340: FTHODO 43579 events total time = 22.44 s average event time = 0.51 ms
> 2018-03-02 21:33:06.340: FTEB 43579 events total time = 12.15 s average event time = 0.28 ms
> 2018-03-02 21:33:06.340: DCHB 43579 events total time = 56948.97 s average event time = 1306.80 ms
> 2018-03-02 21:33:06.341: DCTB 43579 events total time = 15059.81 s average event time = 345.57 ms
> 2018-03-02 21:33:06.341: FTOF 43579 events total time = 89.43 s average event time = 2.05 ms
> 2018-03-02 21:33:06.341: CVT 43579 events total time = 875.40 s average event time = 20.09 ms
> 2018-03-02 21:33:06.342: CTOF 43579 events total time = 51.02 s average event time = 1.17 ms
> 2018-03-02 21:33:06.342: CND 43579 events total time = 8.62 s average event time = 0.20 ms
> 2018-03-02 21:33:06.342: HTCC 43579 events total time = 9.43 s average event time = 0.22 ms
> 2018-03-02 21:33:06.343: LTCC 43579 events total time = 10.26 s average event time = 0.24 ms
> 2018-03-02 21:33:06.343: RICH 43579 events total time = 19.49 s average event time = 0.45 ms
> 2018-03-02 21:33:06.343: EC 43579 events total time = 51.63 s average event time = 1.18 ms
> 2018-03-02 21:33:06.344: EBHB 43579 events total time = 69.41 s average event time = 1.59 ms
> 2018-03-02 21:33:06.344: EBTB 43579 events total time = 59.61 s average event time = 1.37 ms
> 2018-03-02 21:33:06.344: WRITER 43579 events total time = 174.13 s average event time = 4.00 ms
> 2018-03-02 21:33:06.345: TOTAL 43579 events total time = 73486.36 s average event time = 1686.28 ms
> 2018-03-02 21:33:06.345: Average processing time = 27.65 ms
> 2018-03-02 21:33:06.345: Total processing time = 1204.76 s
> 2018-03-02 21:33:06.346: Total orchestrator time = 1212.82 s
> 2018-03-02 21:33:06.346: Processing is complete.
>
>
>
>
>
>
>
> On Sun, Mar 4, 2018 at 11:36 AM, Vardan Gyurjyan <gurjyan at jlab.org <mailto:gurjyan at jlab.org>> wrote:
> Hi All,
>
> Here is an observed behavior running Clara on clonfarm0 (32 core AMD, RH Linux 6).
>
> Clas12 software release: 5a.1.0
> Data file: clas_003191.evio.7.hipo
>
> Running production service chain except FTCAL and FTHODO services: runs with no problems and exceptions, yet there is this long (unexplained) DB activities at the configure stage of the reconstruction (see attached docx file ). This init process can cause DB issues.
>
>
>
>
> Adding FTCLA to the service chain: "[IndexedTable] ---> error.. entry does not exist” console printout for every event (slowing down reconstruction), and after a while out of memory exception (see below).
>
> [IndexedTable] ---> error.. entry does not exist
> [IndexedTable] ---> error.. entry does not exist
> [IndexedTable] ---> error.. entry does not exist
> [IndexedTable] ---> error.. entry does not exist
> [IndexedTable] ---> error.. entry does not exist
> [IndexedTable] ---> error.. entry does not exist
> java.lang.OutOfMemoryError: unable to create new native thread
> at java.lang.Thread.start0(Native Method)
> at java.lang.Thread.start(Thread.java:714)
> at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950)
> at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1357)
> at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
> at org.jlab.coda.xmsg.core.xMsg$1.handle(xMsg.java:568)
> at org.jlab.coda.xmsg.core.xMsgSubscription$Handler.run(xMsgSubscription.java:108)
> at java.lang.Thread.run(Thread.java:745)
> java.lang.OutOfMemoryError: unable to create new native thread
> at java.lang.Thread.start0(Native Method)
> at java.lang.Thread.start(Thread.java:714)
> at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950)
> at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1357)
> at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
> at org.jlab.clara.sys.Service.execute(Service.java:176)
> at org.jlab.clara.sys.Service.access$300(Service.java:53)
> at org.jlab.clara.sys.Service$ServiceCallBack.callback(Service.java:286)
> at org.jlab.coda.xmsg.core.xMsg$1.lambda$handle$0(xMsg.java:568)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> [
>
> Note that this Not the only FT issue (as previously thought), and can be an overall clas12 service engine memory management issue (garbage creation, etc.). Let us first start understanding and addressing DB communication issues, and get read of printouts for every event in any service engine. Printouts are useful for debuting of engines, but not for production service deployments. Clara presents mechanisms to report errors directly to the, triggering specific actions. After these we can return to tackle "out of memory" exception.
>
> Also please take a look at the benchmark results below. We spent almost 3sec/event/core to reconstruct charge particle tracks in DC. This is using 5a.1.0 on online events (Run 3544, currently active). Is this real?
>
>
> 2018-03-04 11:04:17.263: Benchmark results:
> 2018-03-04 11:04:17.264: READER 3000 events total time = 140.63 s average event time = 46.88 ms
> 2018-03-04 11:04:17.264: FTCAL 3000 events total time = 2.73 s average event time = 0.91 ms
> 2018-03-04 11:04:17.265: FTHODO 3000 events total time = 2.61 s average event time = 0.87 ms
> 2018-03-04 11:04:17.266: FTEB 3000 events total time = 2.78 s average event time = 0.93 ms
> 2018-03-04 11:04:17.267: DCHB 3000 events total time = 6354.61 s average event time = 2118.20 ms
> 2018-03-04 11:04:17.267: DCTB 3000 events total time = 2198.50 s average event time = 732.83 ms
> 2018-03-04 11:04:17.268: FTOF 3000 events total time = 11.69 s average event time = 3.90 ms
> 2018-03-04 11:04:17.269: LTCC 3000 events total time = 1.04 s average event time = 0.35 ms
> 2018-03-04 11:04:17.269: EC 3000 events total time = 6.25 s average event time = 2.08 ms
> 2018-03-04 11:04:17.270: EBHB 3000 events total time = 6.99 s average event time = 2.33 ms
> 2018-03-04 11:04:17.271: EBTB 3000 events total time = 5.85 s average event time = 1.95 ms
> 2018-03-04 11:04:17.272: WRITER 3000 events total time = 10.63 s average event time = 3.54 ms
> 2018-03-04 11:04:17.272: TOTAL 3000 events total time = 8744.31 s average event time = 2914.77 ms
>
> Best regards,
> -vardan
>
> _______________________________________________
> Clas12_software mailing list
> Clas12_software at jlab.org <mailto:Clas12_software at jlab.org>
> https://mailman.jlab.org/mailman/listinfo/clas12_software <https://mailman.jlab.org/mailman/listinfo/clas12_software>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mailman.jlab.org/pipermail/clas12_software/attachments/20180304/12d62e55/attachment-0002.html>
More information about the Clas12_software
mailing list