Hi,
Reports indicate the DB backend is not overloaded, so you don't have to
change your DB tunings or db access method.
It looks the access to the filesystem is very slow: GET_INFO_FS stage
takes about 127ms, which means filesystem calls take 127ms which is too
long.
As mysql and robinhood are almost idle (0% CPU), do you know what causes
the server load of 30 ??
This load my explain why accesses are slow.
Thomas
On 04/21/15 10:23, Carmelo Ponti (CSCS) wrote:
Hi Thomas
Thank you very much for your prompt answer.
* An overview of your robinhood pipeline would help determining where it
spends time.
grep STATS /var/log/robinhood.daint.log
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | ======= Resource
Monitor stats ======
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | Trigger #0
(global_usage) : purge running.
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | ============ Purge
stats ============
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | idle purge
threads = 0
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | purge operations
pending = 255
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | purge status:
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | successfully
purged = 76350
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | accessed since last
update = 16
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | moved or deleted
since last update = 1050
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS |
whitelisted/ignored = 1748614
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | total purged volume =
3576313036800 (3.25 TB)
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last file submitted 0
s ago
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last file handled 0
s ago
2015/04/21 09:56:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last file purged 0
s ago
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | ====================
Dumping stats at 2015/04/21 09:57:33 =====================
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | ======== General
statistics =========
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | Daemon start time:
2015/04/20 15:57:20
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | Started modules:
log_reader,purge
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | ChangeLog reader #0:
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | fs_name = snx11026
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | mdt_name = MDT0000
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | reader_id = cl1
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | records read
= 10909648
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | interesting records
= 8816971
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | suppressed records
= 2092677
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | records pending
= 741
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last
received = 2015/04/21 09:56:39
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last read record
time = 2015/04/20 17:21:01.102867
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last read record
id = 5448947569
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last pushed record
id = 5448946682
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last committed
record id = 5448831700
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | last cleared record
id = 5448830961
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | read
speed = 6.60 record/sec
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | processing speed
ratio = 0.03
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS |
status = busy
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | ChangeLog stats:
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | MARK: 0, CREAT:
2425674, MKDIR: 60555, HLINK: 82, SLINK: 2671, MKNOD: 0, UNLNK: 3115664
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | RMDIR: 47692, RENME:
538602, RNMTO: 538602, OPEN: 0, CLOSE: 0, LYOUT: 0, TRUNC: 0
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | SATTR: 4145515,
XATTR: 9103, HSM: 0, MTIME: 25484, CTIME: 4, ATIME: 0
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | ==== EntryProcessor
Pipeline Stats ===
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | Idle threads: 0
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | Id constraints count:
93223 (hash min=0/max=99/avg=5.8)
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | Name constraints count:
82374 (hash min=0/max=1068/avg=5.1)
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | Stage |
Wait | Curr | Done | Total | ms/op |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 0: GET_FID |
0 | 0 | 0 | 0 | 0.00 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 1: GET_INFO_DB
|99977 | 0 | 0 | 9254855 | 0.46 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 2: GET_INFO_FS |
3 | 16 | 4 | 5060149 | 127.36 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 3: REPORTING |
0 | 0 | 0 | 1621148 | 0.00 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 4: PRE_APPLY |
0 | 0 | 0 | 2329020 | 0.00 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 5: DB_APPLY |
0 | 0 | 0 | 2329020 | 0.90 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 6: CHGLOG_CLR |
0 | 0 | 0 | 8742336 | 0.02 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | 7: RM_OLD_ENTRIES |
0 | 0 | 0 | 0 | 0.00 |
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | DB ops:
get=1464691/ins=395683/upd=1224593/rm=707447
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | --- Pipeline stage
details ---
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | GET_INFO_DB : first:
changelog record #5448831728, fid=[0x259aef470:0x49a9:0x0], status=waiting
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | GET_INFO_DB : last:
changelog record #5448946681, fid=[0x257f8da18:0xce40:0x0], status=waiting
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | GET_INFO_FS : first:
changelog record #5448831701, fid=[0x25847ab0d:0x9e8a:0x0],
status=processing
2015/04/21 09:57:33 robinhood@daintrbh01
<mailto:robinhood@daintrbh01>[26268/1] STATS | GET_INFO_FS : last:
changelog record #5448831727, fid=[0x259aef470:0x49a4:0x0], status=done
* Running "sar -d" on you robinhood host for the DB storage disk, is the
last column (%util) close to 100%?
Currently we are using an SSD disk and in this moment last column
(%util) seems OK:
12:10:05 AM dev8-16 9.97 0.00 1150.94 115.40
0.04 4.35 0.78 0.78
12:20:01 AM dev8-16 10.23 0.00 1085.88 106.14
0.04 4.29 0.63 0.64
12:30:05 AM dev8-16 10.59 0.00 1252.76 118.35
0.05 4.38 0.89 0.94
12:40:01 AM dev8-16 23.02 36.74 2117.12 93.58
0.11 4.57 0.57 1.32
12:50:02 AM dev8-16 82.62 37.86 6054.04 73.73
0.42 5.08 0.35 2.92
01:00:04 AM dev8-16 11.73 0.05 1038.67 88.54
0.06 4.72 0.58 0.67
01:10:04 AM dev8-16 14.87 0.59 1267.59 85.27
0.07 4.93 0.50 0.74
01:20:02 AM dev8-16 12.44 0.28 1138.93 91.59
0.06 4.89 0.57 0.71
01:30:02 AM dev8-16 11.79 0.00 1010.65 85.74
0.06 4.80 0.54 0.64
01:40:01 AM dev8-16 12.83 0.00 1214.26 94.68
0.06 4.85 0.71 0.91
01:50:02 AM dev8-16 31.71 159.38 2330.52 78.53
0.15 4.79 0.46 1.46
02:00:04 AM dev8-16 19.18 0.11 1718.61 89.61
0.10 5.09 0.66 1.27
02:10:02 AM dev8-16 22.84 1.94 2110.76 92.49
0.12 5.11 0.60 1.36
02:20:01 AM dev8-16 11.16 0.00 1346.71 120.64
0.05 4.61 0.88 0.98
02:30:01 AM dev8-16 11.25 0.05 1348.59 119.86
0.05 4.23 0.69 0.78
02:40:02 AM dev8-16 20.44 0.05 1873.43 91.64
0.10 4.74 0.55 1.13
02:50:03 AM dev8-16 11.58 0.00 1357.64 117.25
0.05 4.33 0.81 0.94
03:00:01 AM dev8-16 235.51 686.79 18075.37 79.67
1.38 5.87 0.37 8.65
03:10:03 AM dev8-16 131.17 23.25 9851.24 75.28
0.85 6.50 0.42 5.54
03:20:02 AM dev8-16 23.08 3.06 1567.65 68.05
0.14 5.97 0.68 1.57
03:30:02 AM dev8-16 21.13 1.02 1667.58 78.97
0.12 5.88 0.62 1.32
03:40:01 AM dev8-16 11.54 0.00 1340.91 116.18
0.06 4.77 0.96 1.11
03:50:02 AM dev8-16 11.33 0.00 1365.30 120.48
0.06 5.09 0.95 1.07
04:00:03 AM dev8-16 13.15 0.21 1451.96 110.40
0.07 5.12 0.88 1.16
04:10:02 AM dev8-16 11.42 0.00 1345.78 117.85
0.06 4.86 0.97 1.10
04:20:02 AM dev8-16 10.77 0.05 1336.48 124.11
0.05 4.67 0.92 0.99
04:30:01 AM dev8-16 11.35 0.48 1356.11 119.55
0.06 4.93 0.90 1.02
04:40:07 AM dev8-16 26.63 59.74 1958.26 75.79
0.13 4.93 0.45 1.21
04:50:02 AM dev8-16 11.90 0.00 1093.49 91.91
0.05 4.61 0.59 0.70
05:00:06 AM dev8-16 12.20 2.13 1014.56 83.32
0.06 4.80 0.56 0.68
05:10:02 AM dev8-16 12.40 0.54 1080.64 87.21
0.05 4.43 0.52 0.64
05:20:03 AM dev8-16 10.76 0.00 914.27 85.00
0.05 4.40 0.60 0.65
05:30:04 AM dev8-16 10.85 0.11 951.95 87.78
0.05 4.57 0.65 0.71
05:40:06 AM dev8-16 12.02 1.07 1009.64 84.08
0.06 4.86 0.75 0.90
05:50:04 AM dev8-16 11.65 1.07 971.08 83.45
0.06 4.75 0.54 0.63
06:00:06 AM dev8-16 10.87 0.75 865.84 79.69
0.05 4.50 0.63 0.68
06:10:02 AM dev8-16 11.72 0.11 1034.79 88.30
0.06 4.82 0.69 0.81
06:20:02 AM dev8-16 12.79 0.16 1080.31 84.50
0.06 4.73 0.51 0.65
06:30:03 AM dev8-16 10.99 1.39 928.56 84.59
0.05 4.55 0.55 0.61
06:40:06 AM dev8-16 10.74 5.51 893.18 83.69
0.05 4.56 0.65 0.69
06:50:02 AM dev8-16 11.73 0.92 1014.51 86.59
0.05 4.60 0.52 0.61
07:00:01 AM dev8-16 167.35 1058.15 11826.19 76.99
0.88 5.24 0.36 6.10
07:10:01 AM dev8-16 77.19 236.47 5595.96 75.56
0.43 5.55 0.47 3.63
07:20:01 AM dev8-16 219.20 459.52 17196.77 80.55
1.34 6.13 0.40 8.70
07:30:02 AM dev8-16 153.37 109.63 10959.45 72.17
0.86 5.62 0.34 5.21
07:40:10 AM dev8-16 13.91 0.32 1147.46 82.49
0.11 8.02 0.70 0.97
07:50:01 AM dev8-16 13.30 0.00 1175.87 88.44
0.07 5.56 0.64 0.85
08:00:01 AM dev8-16 148.46 515.57 10966.84 77.34
0.88 5.94 0.36 5.35
08:10:05 AM dev8-16 124.70 40.06 9220.48 74.27
0.71 5.72 0.43 5.32
08:20:02 AM dev8-16 24.91 10.71 1595.07 64.47
0.15 5.85 0.72 1.80
08:30:04 AM dev8-16 41.70 207.69 2723.45 70.29
0.23 5.54 0.59 2.45
08:40:02 AM dev8-16 37.94 20.20 2680.39 71.17
0.21 5.49 0.56 2.12
08:50:03 AM dev8-16 44.98 15.02 3061.40 68.40
0.27 6.01 0.58 2.59
09:00:02 AM dev8-16 41.42 10.29 2806.15 67.99
0.23 5.51 0.52 2.15
09:10:01 AM dev8-16 27.64 11.86 1878.74 68.40
0.16 5.61 0.59 1.64
09:20:03 AM dev8-16 21.89 23.48 1452.68 67.44
0.13 5.88 0.65 1.42
09:30:02 AM dev8-16 27.67 65.13 1865.97 69.78
0.14 5.23 0.55 1.52
09:40:02 AM dev8-16 31.31 57.76 2381.06 77.90
0.16 5.15 0.59 1.83
09:50:02 AM dev8-16 27.29 39.61 1859.79 69.60
0.15 5.48 0.55 1.50
10:00:04 AM dev8-16 40.77 48.04 2970.01 74.03
0.21 5.20 0.53 2.16
Average: dev8-16 37.74 65.47 2940.89 79.66
0.21 5.54 0.48 1.82
* If you DB disk backend is not fast, I suggest you use DB request
batching. In robinhood config (EntryProcessor block):
max_batch_size = 1000;
Or you can try increasing processing threads, in EntryProcessor block:
nb_threads = 32 ;
We are using an SSD disk as DB backend so I'm going to increase the
number of threads to 32 and monitor the system.
* Looking at "top", what is the memory and CPU usage of mysqld and
robinhood under full load?
The load of the server in this moment is ~30 (load average: 32.30,
34.40, 35.24) and top of robinhood and mysql give me the following values:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
26268 root 20 0 4373m 1.8g 1428 S 0.0 1.5 316:44.06 robinhood
3217 mysql 20 0 37.6g 1.3g 4320 S 0.0 1.0 1443:00 mysqld
Thank you for the DB tuning advice. I'll try them and let you know.
regards
Carmelo
------------------------------------------------------------------------------
BPM Camp - Free Virtual Workshop May 6th at 10am PDT/1PM EDT
Develop your own process in accordance with the BPMN 2 standard
Learn Process modeling best practices with Bonita BPM through live exercises
http://www.bonitasoft.com/be-part-of-it/events/bpm-camp-virtual- event?utm_
source=Sourceforge_BPM_Camp_5_6_15&utm_medium=email&utm_campaign=VA_SF
_______________________________________________
robinhood-support mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/robinhood-support
