Some cron jobs ( i.e. reports:expire ) launch delete queries that lock some tables

Development
1

Hi,

When migrating to 1.7 I came across with this.

Executing reports i see this in the processlist mysql show:

RAILS_ENV=production rake -s -f /usr/share/foreman/Rakefile

reports:expire days=7
…
…

> show processlist:

xxxxxx
delete FROM sources WHERE (id not IN (SELECT source_id FROM logs ));
xxxxxx

This query makes a lot of SELECTS in "Locked" State.

mysql> show processlist;

··· *+----+--------+-----------+--------+---------+------+--------------+------------------------------------------------------------------------------------------------------+* *| Id | User | Host | db | Command | Time | State | Info 
                >*

±—±-------±----------±-------±--------±-----±-------------±-----------------------------------------------------------------------------------------------------+
| 1 | puppet | localhost | puppet | Query | 2 | Locked |
SELECT sources. FROM sources WHERE sources.digest =
'5079ac11c59ac57c3c7d93bb859fdfa8add5 |*
| 6 | puppet | localhost | puppet | Query | 9 | Locked |
SELECT sources. FROM sources WHERE sources.digest =
'e2077b72593164b9fb6046c741df3272e78d |*
| 13 | puppet | localhost | puppet | Query | 8 | Locked |
SELECT sources. FROM sources WHERE sources.digest =
'30967a4757fbf5342258101cea83ab29b573 |*
| 31 | root | localhost | NULL | Query | 0 | NULL | show
processlist
>
| 32 | puppet | localhost | puppet | Query | 16 | Sending data |
DELETE FROM sources WHERE (id not IN (SELECT source_id FROM logs ))
>
±—±-------±----------±-------±--------±-----±-------------±-----------------------------------------------------------------------------------------------------+
5 rows in set (0.00 sec)

*mysql> *

I add an index to the logs table and now is working much better

BEFORE:

| logs | CREATE TABLE logs (

  • id int(11) NOT NULL AUTO_INCREMENT,*
  • source_id int(11) DEFAULT NULL,*
  • message_id int(11) DEFAULT NULL,*
  • report_id int(11) DEFAULT NULL,*
  • level_id int(11) DEFAULT NULL,*
  • created_at datetime NOT NULL,*
  • updated_at datetime NOT NULL,*
  • PRIMARY KEY (id),*
  • KEY index_logs_on_report_id (report_id),*
  • KEY index_logs_on_message_id (message_id),*
  • KEY index_logs_on_level_id (level_id)*
    ) ENGINE=InnoDB AUTO_INCREMENT=1044534 DEFAULT CHARSET=latin1 |

NOW:

| logs | CREATE TABLE logs (

  • id int(11) NOT NULL AUTO_INCREMENT,*
  • source_id int(11) DEFAULT NULL,*
  • message_id int(11) DEFAULT NULL,*
  • report_id int(11) DEFAULT NULL,*
  • level_id int(11) DEFAULT NULL,*
  • created_at datetime NOT NULL,*
  • updated_at datetime NOT NULL,*
  • PRIMARY KEY (id),*
  • KEY index_logs_on_report_id (report_id),*
  • KEY index_logs_on_message_id (message_id),*
  • KEY index_logs_on_level_id (level_id),*
  • KEY index_logs_on_source_id (source_id)*
    ) ENGINE=InnoDB AUTO_INCREMENT=1044534 DEFAULT CHARSET=latin1 |

Someone experienced something like that when upgrading to 1.7 from 1.1 ?

Thanks

Regards,
Santi

2

This looks like bug #8565, fixed by:

(It'll be in 1.7.3.)

··· On 17/02/15 15:57, Santi Nuñez-Cacho wrote: > Hi, > > When migrating to 1.7 I came across with this. > > Executing reports i see this in the processlist mysql show: > > > # RAILS_ENV=production rake -s -f /usr/share/foreman/Rakefile > reports:expire days=7 > ..... > .. > > > > show processlist: > > xxxxxx > delete FROM `sources` WHERE (id not IN (SELECT source_id FROM `logs` )); > xxxxxx

–
Dominic Cleal
Red Hat Engineering

3

I put in a bug report for it.

http://projects.theforeman.org/issues/10228

4

I did the ~ 1.1 (don't recall specific version but was around there) to
1.7.3. Was experiencing same issue with locked tables and Foreman failing
to respond to ENC requests during the reports:expire run.

My mysql processlist shows the changes from #8565 present, but did not
correct the issue.

··· > show processlist; +----+--------+-----------+--------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+ > Id | User | Host | db | Command | Time | State > Info > +----+--------+-----------+--------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+ > 1 | puppet | localhost | puppet | Query | 307 | Locked > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = 'a100926532eb335a499d37a6bdb525c0d49e | > 3 | puppet | localhost | puppet | Query | 17 | Locked > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = '298db879914a8cf0b602f3235864a495b741 | > 4 | puppet | localhost | puppet | Query | 20 | Locked > SELECT `sources`.* FROM `sources` WHERE `sources`.`id` IN (192) > > 5 | root | localhost | puppet | Query | 0 | NULL > show processlist > > 6 | puppet | localhost | puppet | Query | 311 | Copying to tmp table > DELETE FROM `sources` WHERE (id not IN (SELECT DISTINCT source_id FROM `logs` )) | > 7 | puppet | localhost | puppet | Query | 280 | Locked > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = 'a100926532eb335a499d37a6bdb525c0d49e | > 8 | puppet | localhost | puppet | Query | 283 | Locked > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = 'a100926532eb335a499d37a6bdb525c0d49e | > 9 | puppet | localhost | puppet | Query | 193 | Locked > SELECT `sources`.* FROM `sources` WHERE `sources`.`id` IN (192) > +----+--------+-----------+--------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+ 8 rows in set (0.00 sec)

Running the following did fix it:
ALTER TABLE logs ADD INDEX index_logs_on_source_id (source_id)

Reports::expire runs much much faster (in seconds rather than 10 - 15
minutes) and Foreman doesn’t lock up while it’s running.

On Wednesday, February 18, 2015 at 3:11:48 AM UTC-5, Dominic Cleal wrote:

On 17/02/15 15:57, Santi Nuñez-Cacho wrote:

Hi,

When migrating to 1.7 I came across with this.

Executing reports i see this in the processlist mysql show:

RAILS_ENV=production rake -s -f /usr/share/foreman/Rakefile

reports:expire days=7
…
…

show processlist:

xxxxxx
delete FROM sources WHERE (id not IN (SELECT source_id FROM logs ));
xxxxxx

This looks like bug #8565, fixed by:

https://github.com/theforeman/foreman/commit/9fde85ad830031d38a6786d30a48519344dad446

(It’ll be in 1.7.3.)

–
Dominic Cleal
Red Hat Engineering

5

thanks! could you please open an issue about this ? it looks like its
trivial to fix and will boost performance.

Ohad

··· On Thu, Apr 16, 2015 at 9:09 PM, Roger Spencer wrote:

index_logs_on_source_id

6

Good find, and quite an easy fix. Would you mind filing a bug to add
the index as standard please?

··· On 16/04/15 19:09, Roger Spencer wrote: > I did the ~ 1.1 (don't recall specific version but was around there) to > 1.7.3. Was experiencing same issue with locked tables and Foreman > failing to respond to ENC requests during the reports:expire run. > > My mysql processlist shows the changes from #8565 present, but did not > correct the issue. > > > show processlist; > +----+--------+-----------+--------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+ > > Id | User | Host | db | Command | Time | State > > Info > > > +----+--------+-----------+--------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+ > > 1 | puppet | localhost | puppet | Query | 307 | Locked > > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = > 'a100926532eb335a499d37a6bdb525c0d49e | > > 3 | puppet | localhost | puppet | Query | 17 | Locked > > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = > '298db879914a8cf0b602f3235864a495b741 | > > 4 | puppet | localhost | puppet | Query | 20 | Locked > > SELECT `sources`.* FROM `sources` WHERE `sources`.`id` IN (192) > > > > 5 | root | localhost | puppet | Query | 0 | NULL > > show processlist > > > > 6 | puppet | localhost | puppet | Query | 311 | Copying to tmp > table | DELETE FROM `sources` WHERE (id not IN (SELECT DISTINCT > source_id FROM `logs` )) | > > 7 | puppet | localhost | puppet | Query | 280 | Locked > > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = > 'a100926532eb335a499d37a6bdb525c0d49e | > > 8 | puppet | localhost | puppet | Query | 283 | Locked > > SELECT `sources`.* FROM `sources` WHERE `sources`.`digest` = > 'a100926532eb335a499d37a6bdb525c0d49e | > > 9 | puppet | localhost | puppet | Query | 193 | Locked > > SELECT `sources`.* FROM `sources` WHERE `sources`.`id` IN (192) > > > +----+--------+-----------+--------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+ > 8 rows in set (0.00 sec) > > Running the following did fix it: > ALTER TABLE `logs` ADD INDEX `index_logs_on_source_id` (`source_id`) > > Reports::expire runs much much faster (in seconds rather than 10 - 15 > minutes) and Foreman doesn't lock up while it's running.

–
Dominic Cleal
Red Hat Engineering