TReqS

I have set up a measurement tool based on Elasticsearch+Kibana.

1. Adding measurement in log file (at INFO level)
2. start treqs with a clean config
   clean *.log into /var/log/jtreqs/ directory
   purge file from hpss cache (./files2purge_xyz)
   clean jrequests and jqueues tables
   clean ES index (remove index via GUI)
   without activator (for less logs)
3. inject requests into treqs
   ./trcp.pl -v -p input4trcp.xyz
4. inject log (jtreqs.log) into syslog-NG-ES chain
   nc ccosvm0869 9999 <jtreqs.log
5. Play with kibana (*) ...
6. For test, activator was disabled and treqsd restarted before each run (at least for clean logs)

 count of requests                                  1,000         5,000         10k     20k       50k
 HPSS query d.                                      8,329        40,662      82,766       -       424,579     
 Mysql access d.                                  123,517       591,494   1,270,661       -    11,285,436 
 Dispatching d. (innerProcess method)             137,774       652,097   1,402,293       -    12,051,880 

Major duration comes from DB access
For each request there are
 possibly one insert (INSERT INTO jqueues ...)
 2 updates (UPDATE jrequests  et UPDATE jqueues)
see next examples 

Case queue does not exists : 1 insert + 2 updates

2015-06-30 14:49:48,424 [Dispatcher_req_15759] DEBUG QueuesController - We have to find the queue for tape JS086500, file File{ name: /hpss/in2p3.fr/group/ccin2p3/treqs/RUN01/ccwl0104.22994_000010Mb_0001.dat, size: 10485760}
2015-06-30 14:49:48,425 [Dispatcher_req_15759] DEBUG MySQLBroker - Query: 'INSERT INTO jqueues(status, name, nb_reqs, mediatype_id, owner, byte_size, creation_time) VALUES (?, ?, ?, ?, ?, ?, ?)'
2015-06-30 14:49:48,477 [Dispatcher_req_15759] INFO  MySQLQueueDAO - New queue inserted with id 196 (JS086500)
2015-06-30 14:49:48,477 [Dispatcher_req_15759] INFO  Queue - Queue JS086500 created (id 196).
2015-06-30 14:49:48,478 [Dispatcher_req_15759] DEBUG MySQLBroker - Query: 'UPDATE jrequests SET status = ?, message = ?, queue_id = ?, tape = ?, position = ?, position_offset = ?, level = ?, size = ?, errorcode = 0, submission_time = ? WHERE file = ? AND status < 140'
2015-06-30 14:49:48,527 [Dispatcher_req_15759] DEBUG Queue - Queue JS086500 - CREATED Inserting the reading object at position { position: 1, offset: 0 }
2015-06-30 14:49:48,527 [Dispatcher_req_15759] INFO  Queue - Queue JS086500 - CREATED now contains 1 elements and is owned by bchambon
2015-06-30 14:49:48,528 [Dispatcher_req_15759] DEBUG MySQLBroker - Query: 'UPDATE jqueues SET nb_reqs = ?, owner = ?, byte_size = ?  WHERE id = ?'

Case queue exists : 2 updates

2015-06-30 14:49:54,638 [Dispatcher_req_15767] INFO  QueuesController - A queue with status CREATED already exists.
2015-06-30 14:49:54,639 [Dispatcher_req_15767] DEBUG MySQLBroker - Query: 'UPDATE jrequests SET status = ?, message = ?, queue_id = ?, tape = ?, position = ?, position_offset = ?, level = ?, size = ?, errorcode = 0, submission_time = ? WHERE file = ? AND status < 140'
2015-06-30 14:49:54,691 [Dispatcher_req_15767] DEBUG Queue - Queue JS088200 - CREATED Inserting the reading object at position { position: 7, offset: 0 }
2015-06-30 14:49:54,692 [Dispatcher_req_15767] INFO  Queue - Queue JS088200 - CREATED now contains 3 elements and is owned by bchambon
2015-06-30 14:49:54,692 [Dispatcher_req_15767] DEBUG MySQLBroker - Query: 'UPDATE jqueues SET nb_reqs = ?, owner = ?, byte_size = ?  WHERE id = ?'

• Values displayed vith kibana have been have been faced with ... grep | awk ...
  

  grep "Hpss query attributes duration" jtreqs.log | awk 'BEGIN {n=0; s=0} {n++; s+=$15} END {printf("total for %d requests is %s ms \n", n, s)}'
  
  grep "Dispatching duration (innerProcess method)" jtreqs.log | awk 'BEGIN {n=0; s=0} {n++; s+=$12} END {printf("total for %d requests is %s ms \n", n, s)}'
  
  grep "Mysql access duration" jtreqs.log | awk 'BEGIN {n=0; s=0} {n++; s+=$13} END {printf("total for %d requests is %s ms \n", n, s)}'
  total for 2163 requests is 123446 ms