I have set up a measurement tool based on Elasticsearch+Kibana.
Method
- Adding measurement in log file (at INFO level)
- 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)
- inject requests into treqs
./trcp.pl -v -p input4trcp.xyz
- inject log (jtreqs.log) into syslog-NG-ES chain
nc ccosvm0869 9999 <jtreqs.log
- Play with kibana (*) ...
- For test, activator was disabled and treqsd restarted before each run (at least for clean logs)
Here are data (duration (d.) in millis (ms)
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
Updated by