[Clas12_software] DB initialization and FTCAL
Francois-Xavier Girod
fxgirod at jlab.org
Sun Mar 4 11:48:06 EST 2018
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_00
3512.evio.1400.hipo
[READER] ----> opening current file : /u/scratch/fxgirod/test/clas_00
3512.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_00
3512.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_00
3512.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_00
3512.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> 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
> 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/9ea39e9d/attachment-0002.html>
More information about the Clas12_software
mailing list