Recent changes on the billing pages - CPU hogging of poll-billing.php
Hi,
I would like to start with that the recent changes look really good on the billing pages. Excellent job, I like it.
Over the last few weeks minor changes have been done to these pages and I was wondering if anything was also done to the file: /opt/observium/poll-billing.php or the tables used for it.
That process currently takes about 40 minutes on our environment, while I hoped that upgrading to an Equillogic with 16 SAS drives with RAID10 for more IOPS would fix the issue, while it did improve a bit, the result is the similar. Could it be that there are indices missing? Or is there something else which could be done that might improve this?
I can create some indices myself to see if things improve in a shadow environment, but I'm not sure if that would break things with future SVN update's if done in production ?
Regards, Erik Bais
From the mysql-slow-query log:
# User@Host: observium[observium] @ localhost [] # Query_time: 0.002977 Lock_time: 0.000189 Rows_sent: 2 Rows_examined: 278 SET timestamp=1343723771; SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='68' AND I.port_id = P.port_id AND D.device_id = I.device_id; # Time: 120731 10:36:27 # User@Host: observium[observium] @ localhost [] # Query_time: 0.006157 Lock_time: 0.000172 Rows_sent: 1 Rows_examined: 276 SET timestamp=1343723787; SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='170' AND I.port_id = P.port_id AND D.device_id = I.device_id; # User@Host: observium[observium] @ localhost [] # Query_time: 0.003924 Lock_time: 0.000129 Rows_sent: 1 Rows_examined: 276 SET timestamp=1343723787; SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='156' AND I.port_id = P.port_id AND D.device_id = I.device_id; # User@Host: observium[observium] @ localhost [] # Query_time: 0.002853 Lock_time: 0.000198 Rows_sent: 2 Rows_examined: 278 SET timestamp=1343723787; SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='140' AND I.port_id = P.port_id AND D.device_id = I.device_id; # User@Host: observium[observium] @ localhost [] # Query_time: 0.001970 Lock_time: 0.000166 Rows_sent: 1 Rows_examined: 276 SET timestamp=1343723787; SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='116' AND I.port_id = P.port_id AND D.device_id = I.device_id;
Top output:
Tasks: 189 total, 1 running, 188 sleeping, 0 stopped, 0 zombie Cpu0 : 73.6%us, 16.2%sy, 0.0%ni, 9.1%id, 1.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu1 : 74.2%us, 16.2%sy, 0.0%ni, 9.6%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu2 : 75.6%us, 14.0%sy, 0.0%ni, 10.0%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st Cpu3 : 72.8%us, 16.4%sy, 0.0%ni, 10.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 12307228k total, 1980332k used, 10326896k free, 141572k buffers Swap: 7340028k total, 0k used, 7340028k free, 1098304k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 17981 mysql 20 0 4058m 208m 7840 S 329 1.7 284:02.92 mysqld 25265 root 20 0 192m 16m 6608 S 1 0.1 0:10.13 php 13586 root 20 0 192m 16m 6608 S 1 0.1 0:00.69 php 16609 root 20 0 192m 16m 6608 S 1 0.1 0:05.56 php 11807 root 20 0 192m 16m 6608 S 1 0.1 0:06.75 php 26474 root 20 0 192m 16m 6608 S 1 0.1 0:03.88 php
Processes running after 1.5 hours:
root 2272 2259 0 09:50 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 2279 2272 0 09:50 ? 00:00:08 php /opt/observium/poll-billing.php root 3757 3747 0 10:25 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 3760 3757 0 10:25 ? 00:00:02 php /opt/observium/poll-billing.php root 6983 6972 0 09:55 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 6991 6983 0 09:55 ? 00:00:07 php /opt/observium/poll-billing.php root 8755 8743 0 10:30 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 8759 8755 0 10:30 ? 00:00:01 php /opt/observium/poll-billing.php root 11514 11501 0 09:25 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 11522 11514 0 09:25 ? 00:00:13 php /opt/observium/poll-billing.php root 11803 11793 0 10:00 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 11807 11803 0 10:00 ? 00:00:06 php /opt/observium/poll-billing.php root 13578 13566 0 10:35 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 13586 13578 0 10:35 ? 00:00:00 php /opt/observium/poll-billing.php root 15995 15983 0 09:30 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 15998 15995 0 09:30 ? 00:00:11 php /opt/observium/poll-billing.php root 16605 16595 0 10:05 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 16609 16605 0 10:05 ? 00:00:05 php /opt/observium/poll-billing.php root 20583 20573 0 09:35 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 20586 20583 0 09:35 ? 00:00:11 php /opt/observium/poll-billing.php root 21514 21504 0 10:10 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 21519 21514 0 10:10 ? 00:00:04 php /opt/observium/poll-billing.php root 25260 25252 0 09:40 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 25265 25260 0 09:40 ? 00:00:10 php /opt/observium/poll-billing.php root 26469 26457 0 10:15 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 26474 26469 0 10:15 ? 00:00:03 php /opt/observium/poll-billing.php root 29987 29976 0 09:45 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 29990 29987 0 09:45 ? 00:00:09 php /opt/observium/poll-billing.php root 31342 31332 0 10:20 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1 root 31347 31342 0 10:20 ? 00:00:02 php /opt/observium/poll-billing.php
root@portal:/var/log/mysql# ps -ef | grep poll-billing | wc -l 30
Delete any entries from your ports_in_measurements and ports_out_measurements tables older than 10 minutes.
We'll do this automatically at some point, but not yet.
adam.
On 31/07/2012 10:46, Erik Bais wrote:
Hi,
I would like to start with that the recent changes look really good on the billing pages. Excellent job, I like it.
Over the last few weeks minor changes have been done to these pages and I was wondering if anything was also done to the file: /opt/observium/poll-billing.php or the tables used for it.
That process currently takes about 40 minutes on our environment, while I hoped that upgrading to an Equillogic with 16 SAS drives with RAID10 for more IOPS would fix the issue, while it did improve a bit, the result is the similar.
Could it be that there are indices missing? Or is there something else which could be done that might improve this?
I can create some indices myself to see if things improve in a shadow environment, but I'm not sure if that would break things with future SVN update's if done in production ?
Regards,
Erik Bais
From the mysql-slow-query log:
# User@Host: observium[observium] @ localhost []
# Query_time: 0.002977 Lock_time: 0.000189 Rows_sent: 2 Rows_examined: 278
SET timestamp=1343723771;
SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='68' AND I.port_id = P.port_id AND D.device_id = I.device_id;
# Time: 120731 10:36:27
# User@Host: observium[observium] @ localhost []
# Query_time: 0.006157 Lock_time: 0.000172 Rows_sent: 1 Rows_examined: 276
SET timestamp=1343723787;
SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='170' AND I.port_id = P.port_id AND D.device_id = I.device_id;
# User@Host: observium[observium] @ localhost []
# Query_time: 0.003924 Lock_time: 0.000129 Rows_sent: 1 Rows_examined: 276
SET timestamp=1343723787;
SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='156' AND I.port_id = P.port_id AND D.device_id = I.device_id;
# User@Host: observium[observium] @ localhost []
# Query_time: 0.002853 Lock_time: 0.000198 Rows_sent: 2 Rows_examined: 278
SET timestamp=1343723787;
SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='140' AND I.port_id = P.port_id AND D.device_id = I.device_id;
# User@Host: observium[observium] @ localhost []
# Query_time: 0.001970 Lock_time: 0.000166 Rows_sent: 1 Rows_examined: 276
SET timestamp=1343723787;
SELECT * FROM `bill_ports` as P, `ports` as I, `devices` as D WHERE P.bill_id='116' AND I.port_id = P.port_id AND D.device_id = I.device_id;
Top output:
Tasks: 189 total, 1 running, 188 sleeping, 0 stopped, 0 zombie
Cpu0 : 73.6%us, 16.2%sy, 0.0%ni, 9.1%id, 1.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu1 : 74.2%us, 16.2%sy, 0.0%ni, 9.6%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu2 : 75.6%us, 14.0%sy, 0.0%ni, 10.0%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 : 72.8%us, 16.4%sy, 0.0%ni, 10.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 12307228k total, 1980332k used, 10326896k free, 141572k buffers
Swap: 7340028k total, 0k used, 7340028k free, 1098304k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17981 mysql 20 0 4058m 208m 7840 S 329 1.7 284:02.92 mysqld
25265 root 20 0 192m 16m 6608 S 1 0.1 0:10.13 php
13586 root 20 0 192m 16m 6608 S 1 0.1 0:00.69 php
16609 root 20 0 192m 16m 6608 S 1 0.1 0:05.56 php
11807 root 20 0 192m 16m 6608 S 1 0.1 0:06.75 php
26474 root 20 0 192m 16m 6608 S 1 0.1 0:03.88 php
Processes running after 1.5 hours:
root 2272 2259 0 09:50 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 2279 2272 0 09:50 ? 00:00:08 php /opt/observium/poll-billing.php
root 3757 3747 0 10:25 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 3760 3757 0 10:25 ? 00:00:02 php /opt/observium/poll-billing.php
root 6983 6972 0 09:55 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 6991 6983 0 09:55 ? 00:00:07 php /opt/observium/poll-billing.php
root 8755 8743 0 10:30 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 8759 8755 0 10:30 ? 00:00:01 php /opt/observium/poll-billing.php
root 11514 11501 0 09:25 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 11522 11514 0 09:25 ? 00:00:13 php /opt/observium/poll-billing.php
root 11803 11793 0 10:00 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 11807 11803 0 10:00 ? 00:00:06 php /opt/observium/poll-billing.php
root 13578 13566 0 10:35 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 13586 13578 0 10:35 ? 00:00:00 php /opt/observium/poll-billing.php
root 15995 15983 0 09:30 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 15998 15995 0 09:30 ? 00:00:11 php /opt/observium/poll-billing.php
root 16605 16595 0 10:05 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 16609 16605 0 10:05 ? 00:00:05 php /opt/observium/poll-billing.php
root 20583 20573 0 09:35 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 20586 20583 0 09:35 ? 00:00:11 php /opt/observium/poll-billing.php
root 21514 21504 0 10:10 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 21519 21514 0 10:10 ? 00:00:04 php /opt/observium/poll-billing.php
root 25260 25252 0 09:40 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 25265 25260 0 09:40 ? 00:00:10 php /opt/observium/poll-billing.php
root 26469 26457 0 10:15 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 26474 26469 0 10:15 ? 00:00:03 php /opt/observium/poll-billing.php
root 29987 29976 0 09:45 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 29990 29987 0 09:45 ? 00:00:09 php /opt/observium/poll-billing.php
root 31342 31332 0 10:20 ? 00:00:00 /bin/sh -c /opt/observium/poll-billing.php >> /dev/null 2>&1
root 31347 31342 0 10:20 ? 00:00:02 php /opt/observium/poll-billing.php
root@portal:/var/log/mysql# ps -ef | grep poll-billing | wc -l
30
observium mailing list observium@observium.org http://postman.memetic.org/cgi-bin/mailman/listinfo/observium
participants (2)
-
Adam Armstrong -
Erik Bais