[dev.icinga.com #12258] icinga2 IDO reload performance significant slower with latest snapshot release #4418

icinga-migration · 2016-07-29T13:50:28Z

This issue has been migrated from Redmine: https://dev.icinga.com/issues/12258

Created by hvhaugwitz on 2016-07-29 13:50:28 +00:00

Assignee: mfriedrich
Status: Resolved (closed on 2016-08-11 16:36:08 +00:00)
Target Version: 2.5.0
Last Update: 2016-08-16 18:19:33 +00:00 (in Redmine)

Icinga Version: 2.5.0
Backport?: Not yet backported
Include in Changelog: 0

The MySQL IDO reload performance is significant slower with the latest icinga2
snapshot relesase (version: v2.4.10-565-ga3815e4) than with 2.4.10-1:

2.4.10-1:

[2016-07-29 13:57:55 +0200] information/IdoMysqlConnection: MySQL IDO instance id: 1 (schema version: '1.14.0')
[2016-07-29 13:58:10 +0200] information/IdoMysqlConnection: Query queue items: 2036, query rate: 0.7/s (42/min 42/5min 42/15min); empty in infinite time, your database isn't able to keep up
[2016-07-29 13:58:25 +0200] information/IdoMysqlConnection: Query queue items: 2143, query rate: 1426.75/s (85605/min 85605/5min 85605/15min);
[2016-07-29 13:58:40 +0200] information/IdoMysqlConnection: Query queue items: 4177, query rate: 3693.25/s (221595/min 221595/5min 221595/15min);
[2016-07-29 13:58:55 +0200] information/IdoMysqlConnection: Query queue items: 5225, query rate: 4943.28/s (296597/min 296639/5min 296639/15min);
[2016-07-29 13:59:10 +0200] information/IdoMysqlConnection: Query queue items: 9798, query rate: 7225.77/s (433546/min 433588/5min 433588/15min);
[2016-07-29 13:59:25 +0200] information/IdoMysqlConnection: Query queue items: 12296, query rate: 7543.7/s (452622/min 572246/5min 572246/15min);
[2016-07-29 13:59:39 +0200] information/IdoMysqlConnection: Finished reconnecting to MySQL IDO database in 104.05 second(s).

v2.4.10-565-ga3815e4:

[2016-07-29 14:18:45 +0200] information/IdoMysqlConnection: MySQL IDO instance id: 1 (schema version: '1.14.1')
[2016-07-29 14:19:00 +0200] information/IdoMysqlConnection: Query queue items: 41, query rate: 417.283/s (25037/min 25037/5min 25037/15min);
[2016-07-29 14:19:15 +0200] information/IdoMysqlConnection: Query queue items: 2070, query rate: 1250.65/s (75039/min 75039/5min 75039/15min);
[2016-07-29 14:19:30 +0200] information/IdoMysqlConnection: Query queue items: 2113, query rate: 1667.33/s (100040/min 100040/5min 100040/15min);
[2016-07-29 14:19:45 +0200] information/IdoMysqlConnection: Query queue items: 4144, query rate: 2500.7/s (150042/min 150042/5min 150042/15min);
[2016-07-29 14:20:00 +0200] information/IdoMysqlConnection: Query queue items: 4187, query rate: 2500.1/s (150006/min 175043/5min 175043/15min);
[2016-07-29 14:20:15 +0200] information/IdoMysqlConnection: Query queue items: 6215, query rate: 2500.1/s (150006/min 200044/5min 200044/15min);
[2016-07-29 14:20:30 +0200] information/IdoMysqlConnection: Query queue items: 6259, query rate: 2500.1/s (150006/min 250046/5min 250046/15min);
[2016-07-29 14:20:45 +0200] information/IdoMysqlConnection: Query queue items: 8289, query rate: 2500.1/s (150006/min 275047/5min 275047/15min);
[2016-07-29 14:21:00 +0200] information/IdoMysqlConnection: Query queue items: 8333, query rate: 2500.1/s (150006/min 325049/5min 325049/15min);
[2016-07-29 14:21:15 +0200] information/IdoMysqlConnection: Query queue items: 10362, query rate: 2916.78/s (175007/min 375051/5min 375051/15min);
[2016-07-29 14:21:30 +0200] information/IdoMysqlConnection: Query queue items: 10405, query rate: 2916.78/s (175007/min 400052/5min 400052/15min);
[2016-07-29 14:21:45 +0200] information/IdoMysqlConnection: Query queue items: 12436, query rate: 2916.78/s (175007/min 450054/5min 450054/15min);
[2016-07-29 14:22:00 +0200] information/IdoMysqlConnection: Query queue items: 12479, query rate: 2916.78/s (175007/min 475055/5min 475055/15min);
[2016-07-29 14:22:13 +0200] information/IdoMysqlConnection: Finished reconnecting to MySQL IDO database in 208.135 second(s).

Though the number of queries during the reload is a little bit higher the
current stable release needs only half of the time to reconnect to the
database.

As unfortunately #11501 is not be fixed in 2.5.0 it would be important that
the IDO reload performance stays at least at the same level as before.

Some data about the setup:

information/ConfigItem: Instantiated 1 FileLogger.
information/ConfigItem: Instantiated 2 ApiUsers.
information/ConfigItem: Instantiated 1 ApiListener.
information/ConfigItem: Instantiated 3 Zones.
information/ConfigItem: Instantiated 2 Endpoints.
information/ConfigItem: Instantiated 1 IdoMysqlConnection.
information/ConfigItem: Instantiated 59 CheckCommands.
information/ConfigItem: Instantiated 4 NotificationCommands.
information/ConfigItem: Instantiated 1 IcingaApplication.
information/ConfigItem: Instantiated 21832 Dependencies.
information/ConfigItem: Instantiated 1 EventCommand.
information/ConfigItem: Instantiated 1984 Hosts.
information/ConfigItem: Instantiated 9 HostGroups.
information/ConfigItem: Instantiated 34 Users.
information/ConfigItem: Instantiated 7 UserGroups.
information/ConfigItem: Instantiated 31290 Services.
information/ConfigItem: Instantiated 5 TimePeriods.
information/ConfigItem: Instantiated 7 ServiceGroups.
information/ConfigItem: Instantiated 1 CheckerComponent.
information/ConfigItem: Instantiated 1 ExternalCommandListener.
information/ConfigItem: Instantiated 1 GraphiteWriter.
information/ConfigItem: Instantiated 1 NotificationComponent.

# cat /etc/icinga2/features-enabled/ido-mysql.conf
library "db_ido_mysql"

object IdoMysqlConnection "ido-mysql" {
  user = "icinga2",
  password = "",
  socket_path = "/run/mysqld/mysqld.sock",
  database = "icinga2"
}

We have a huge amount of custom variables:

mysql> select count(*) from icinga_customvariables;
+----------+
| count(*) |
+----------+
|   172512 |
+----------+

Attachments

icinga2_snapshot_ido_queries_summary.txt hvhaugwitz - 2016-07-29 17:34:13 +00:00
icinga2_stable_ido_queries_summary.txt hvhaugwitz - 2016-07-29 17:34:13 +00:00
icinga2_snapshot_query_log.gz mfriedrich - 2016-08-11 16:34:42 +00:00
icinga2_2.4.10_query_log.gz mfriedrich - 2016-08-11 16:34:42 +00:00

Changesets

2016-08-01 15:54:03 +00:00 by mfriedrich 1074102

DB IDO: Use upsert and session token for comment/downtime updates

refs #12258

2016-08-02 12:37:16 +00:00 by mfriedrich cd5c936

DB IDO: Use upsert and session token for comment/downtime updates

refs #12258
fixes #12288

2016-08-02 13:05:21 +00:00 by mfriedrich 1ff6939

Fix missing MySQL session_token changes

refs #12258
refs #12288

2016-08-03 14:15:22 +00:00 by mfriedrich 00f05a8

DB IDO: Do not try to delete downtimes when using the session_token

Missed it after modifying the comments.

refs #12258
refs #12288

2016-08-11 15:43:39 +00:00 by mfriedrich d84872f

DB IDO: Really do not clear downtimes on checkable upsert

refs #12258
refs #12288

Relations:

relates #11688
relates #12288

The text was updated successfully, but these errors were encountered:

icinga-migration · 2016-07-29T15:16:27Z

Updated by mfriedrich on 2016-07-29 15:16:27 +00:00

Status changed from New to Feedback
Assigned to set to hvhaugwitz

2.4.10 is not directly comparable as the event which logs "finished reconnect" is not necessarily really at the end. If there were other queries re-inserted into the query queue after it happened you won't see them (at least not in your log summary). We've also changed the way how transactions are fired so there will be more BEGIN/COMMIT queries inside the current snapshot. One thing that's gone are the numerous DELETE and INSERT statements for group members, those are UPDATE and one INSERT if not existing, plus the DELETE on the session token at the end.

Does your schema have all the 2.5.0.sql changes applied?

One thing which is interesting - your database is only processing half of the queries in the same time. I'd investigate on the database side (show processlist and slow query logging) if there's something changed over there.

I don't get the relation to #11501 - that's a different topic (API) and not related to the IDO database.

icinga-migration · 2016-07-29T17:01:03Z

Updated by hvhaugwitz on 2016-07-29 17:01:03 +00:00

dnsmichi wrote:

Does your schema have all the 2.5.0.sql changes applied?

Yes, at least the changes that come with the icinga2-ido-mysql package.

One thing which is interesting - your database is only processing half of the queries in the same time. I'd investigate on the database side (show processlist and slow query logging) if there's something changed over there.

The database is on the same host as icinga2 and the only change was the upgrade from stable to snapshot release. The slow query log is empty.

I don't get the relation to #11501 - that's a different topic (API) and not related to the IDO database.

With #11501 implemented there would be no need for reloads on host configuration changes ;-)

icinga-migration · 2016-07-29T17:34:26Z

Updated by hvhaugwitz on 2016-07-29 17:34:26 +00:00

File added icinga2_snapshot_ido_queries_summary.txt
File added icinga2_stable_ido_queries_summary.txt

attached the summaries of the queries (as discussed with gunnarbeutner via irc)

icinga-migration · 2016-07-30T19:17:40Z

Updated by tobiasvdk on 2016-07-30 19:17:40 +00:00

What I also confirm is that icinga doesn't do as many queries/s as it did "before". Afair, in my case it was ~9000 q/s for ~2 minutes and then it dropped to ~7500 q/s. Now it's only 5500 - 6000 q/s (without the burst just after the reload).

icinga-migration · 2016-08-01T08:46:35Z

Updated by mfriedrich on 2016-08-01 08:46:35 +00:00

  33276 DELETE FROM icinga_scheduleddowntime    
  33276 DELETE FROM icinga_comments

icinga-migration · 2016-08-02T12:32:41Z

Updated by mfriedrich on 2016-08-02 12:32:41 +00:00

Relates set to 11688

icinga-migration · 2016-08-02T12:39:04Z

Updated by mfriedrich on 2016-08-02 12:39:04 +00:00

I assume the related change with #11688 and deleting any stale comment/downtime objects turns into multiple DELETE statements for each object. Even given a database index it will still cause some time. As we now have an upsert mechanism implemented for #12210 it makes sense to go the same route here with an additional session_token. Will link the follow-up ticket,

Please test git commit cd5c936

icinga-migration · 2016-08-02T12:40:03Z

Updated by mfriedrich on 2016-08-02 12:40:03 +00:00

Relates set to 12288

icinga-migration · 2016-08-02T12:57:07Z

Updated by hvhaugwitz on 2016-08-02 12:57:07 +00:00

dnsmichi wrote:

Please test git commit cd5c936

Thanks, will do the test later.

It seems that in your commit the session_token column and the idx_downtimes_session_del index for the icinga_sheduleddowntime table is missing in lib/db_ido_mysql/schema/mysql.sql

icinga-migration · 2016-08-02T13:06:26Z

Updated by mfriedrich on 2016-08-02 13:06:26 +00:00

Correct, thanks for noticing so fast. Shouldn't do 3 issues at the same time. Thanks fixed.

icinga-migration · 2016-08-03T14:07:21Z

Updated by hvhaugwitz on 2016-08-03 14:07:21 +00:00

Today I've tested v2.4.10-583-g4544014:

172526 UPDATE icinga_customvariablestatus
172525 UPDATE icinga_customvariables
 38170 UPDATE icinga_servicegroup_members
 33277 DELETE FROM icinga_scheduleddowntime
 31318 UPDATE icinga_servicestatus
 31290 UPDATE icinga_services
 19482 INSERT INTO icinga_servicedependencies
 15868 UPDATE icinga_hoststatus
  3916 UPDATE icinga_hostgroup_members
  2351 INSERT INTO icinga_hostdependencies
  1984 UPDATE icinga_hosts
   368 INSERT INTO icinga_host_parenthosts
    88 INSERT INTO icinga_runtimevariables
    74 UPDATE icinga_objects
    64 UPDATE icinga_commands
    34 UPDATE icinga_contactstatus
    34 UPDATE icinga_contacts
    30 UPDATE icinga_contactgroup_members
    24 INSERT INTO icinga_timeperiod_timeranges
    22 UPDATE icinga_programstatus
    22 DELETE FROM icinga_runtimevariables
     9 UPDATE icinga_servicegroups
     9 UPDATE icinga_hostgroups
     7 UPDATE icinga_contactgroups
     6 DELETE FROM icinga_timeperiod_timeranges
     5 UPDATE icinga_timeperiods
     3 UPDATE icinga_zonestatus
     3 UPDATE icinga_zones
     2 UPDATE icinga_endpointstatus
     2 UPDATE icinga_endpoints
     1 SELECT FROM icinga_zones
     1 SELECT FROM icinga_timeperiods
     1 SELECT FROM icinga_services
     1 SELECT FROM icinga_servicegroups
     1 SELECT FROM icinga_programstatus
     1 SELECT FROM icinga_objects
     1 SELECT FROM icinga_instances
     1 SELECT FROM icinga_hosts
     1 SELECT FROM icinga_hostgroups
     1 SELECT FROM icinga_endpoints
     1 SELECT FROM icinga_dbversion
     1 SELECT FROM icinga_contacts
     1 SELECT FROM icinga_contactgroups
     1 SELECT FROM icinga_commands
     1 INSERT INTO icinga_conninfo
     1 DELETE FROM icinga_servicegroup_members
     1 DELETE FROM icinga_servicedependencies
     1 DELETE FROM icinga_service_contacts
     1 DELETE FROM icinga_service_contactgroups
     1 DELETE FROM icinga_host_parenthosts
     1 DELETE FROM icinga_hostgroup_members
     1 DELETE FROM icinga_hostdependencies
     1 DELETE FROM icinga_host_contacts
     1 DELETE FROM icinga_host_contactgroups
     1 DELETE FROM icinga_customvariablestatus
     1 DELETE FROM icinga_customvariables
     1 DELETE FROM icinga_contact_notificationcommands
     1 DELETE FROM icinga_contactgroup_members
     1 DELETE FROM icinga_contact_addresses
     1 DELETE FROM icinga_comments

The 33276 'DELETE FROM icinga_scheduleddowntime' statements are still there.
At a first glance I assume the 'RemoveDowntimeInternal(queries, downtime);' line in
'DbEvents::AddDowntime' needs to be removed too.

Apart from that the change has no measurable effect to the reconnection time of icinga2:

[2016-08-03 12:45:48 +0200] information/IdoMysqlConnection: MySQL IDO instance id: 1 (schema version: '1.14.1')
[2016-08-03 12:46:03 +0200] information/IdoMysqlConnection: Query queue items: 43, query rate: 417.283/s (25037/min 25037/5min 25037/15min);
[2016-08-03 12:46:18 +0200] information/IdoMysqlConnection: Query queue items: 2072, query rate: 1250.65/s (75039/min 75039/5min 75039/15min);
[2016-08-03 12:46:33 +0200] information/IdoMysqlConnection: Query queue items: 2115, query rate: 1667.33/s (100040/min 100040/5min 100040/15min);
[2016-08-03 12:46:48 +0200] information/IdoMysqlConnection: Query queue items: 4146, query rate: 2500.7/s (150042/min 150042/5min 150042/15min);
[2016-08-03 12:47:03 +0200] information/IdoMysqlConnection: Query queue items: 4189, query rate: 2500.1/s (150006/min 175043/5min 175043/15min);
[2016-08-03 12:47:18 +0200] information/IdoMysqlConnection: Query queue items: 6218, query rate: 2500.1/s (150006/min 225045/5min 225045/15min);
[2016-08-03 12:47:33 +0200] information/IdoMysqlConnection: Query queue items: 6261, query rate: 2500.1/s (150006/min 250046/5min 250046/15min);
[2016-08-03 12:47:48 +0200] information/IdoMysqlConnection: Query queue items: 8292, query rate: 2500.1/s (150006/min 300048/5min 300048/15min);
[2016-08-03 12:48:03 +0200] information/IdoMysqlConnection: Query queue items: 8335, query rate: 2500.1/s (150006/min 325049/5min 325049/15min);
[2016-08-03 12:48:18 +0200] information/IdoMysqlConnection: Query queue items: 10364, query rate: 2500.1/s (150006/min 375051/5min 375051/15min);
[2016-08-03 12:48:33 +0200] information/IdoMysqlConnection: Query queue items: 10407, query rate: 2500.1/s (150006/min 400052/5min 400052/15min);
[2016-08-03 12:48:48 +0200] information/IdoMysqlConnection: Query queue items: 12438, query rate: 2916.78/s (175007/min 450054/5min 450054/15min);
[2016-08-03 12:49:03 +0200] information/IdoMysqlConnection: Query queue items: 12481, query rate: 2916.78/s (175007/min 475055/5min 475055/15min);
[2016-08-03 12:49:17 +0200] information/IdoMysqlConnection: Finished reconnecting to MySQL IDO database in 208.446 second(s).

icinga-migration · 2016-08-03T14:24:06Z

Updated by mfriedrich on 2016-08-03 14:24:06 +00:00

Thanks, corrected that with the downtimes delete. Other than that there are no significant changes - except for additional indexes for select/delete queries which may influence insert queries and their time to process.

You're using quite a lot of custom vars and service groups, that's the only thing I can see for now from the query counts. The changed DELETE/INSERT into an upsert might have an influence which could maybe analysed from within MySQL itself (different strategy for query execution, or execution time).

icinga-migration · 2016-08-03T17:55:24Z

Updated by hvhaugwitz on 2016-08-03 17:55:24 +00:00

I don't think the queries themselves are the problem here. They are more or less the same as with 2.4.10-1.

Something has been changed in the snapshot version that causes icinga2 to process the configuration a lot more slowly than before.

Please let me know if I can do anything to debug this issue further.

icinga-migration · 2016-08-08T14:35:21Z

Updated by gbeutner on 2016-08-08 14:35:21 +00:00

Status changed from Feedback to Assigned
Assigned to changed from hvhaugwitz to mfriedrich
Target Version set to 2.5.0

icinga-migration · 2016-08-11T16:36:08Z

Updated by mfriedrich on 2016-08-11 16:36:08 +00:00

File added icinga2_2.4.10_query_log.gz
File added icinga2_snapshot_query_log.gz
Status changed from Assigned to Resolved
Done % changed from 0 to 100
Include in Changelog changed from 1 to 0

Steps to reproduce

Generate lots of services and simulate a config dump (10k services, 100k custom attributes)
Log the queries and diff the time from startup to the last session_token delete queries.
Compare 2.4.10 and 2.5.0 snapshot.
Slightly different to a native 2.4.10 env - additional indexes on the schema, but both versions use the same thing.
The stats logger thingy cannot be used for comparisons, neither the event for logging nor for updating the stats was working accurately in 2.4.10.

Test environment

object IcingaApplication "app" {
  enable_host_checks = false
  enable_service_checks = false
}

const countHosts = 1000;
const countServices = 10;


for (i in range(countHosts)) {
  object Host "many-test-" + i {
    check_command = "random"
  }
}

for (j in range(countServices)) {
  apply Service "many-test-" + j {
    check_command = "random"

    for (k in range(10)) {
      vars["key" + k] = k
    }

    assign where match("many*", host.name)
  }
}

icinga2 daemon -x debug | grep 'Query: ' > icinga2_2.4.10_query_log
icinga2 daemon -x debug | grep 'Query: ' > icinga2_snapshot_query_log

MariaDB [icinga]> select count(*) from icinga_objects where is_active=1;
+----------+
| count(*) |
+----------+
|    11400 |
+----------+
1 row in set (0.01 sec)

MariaDB [icinga]> select count(*) from icinga_customvariables;
+----------+
| count(*) |
+----------+
|   101044 |
+----------+
1 row in set (0.04 sec)

2.4.10

There is a bug in 2.4.10 where the final DELETE session_token does not happen at the end, but somewhere before. We'll therefore take the last query into account before the normal program status update intervals happen.

80 seconds.

[2016-08-11 18:23:17 +0200] debug/IdoMysqlConnection: Query: SELECT @@global.max_allowed_packet AS max_allowed_packet
...
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_customvariables WHERE session_token <> 1470932597
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: INSERT INTO icinga_commands (command_line, config_type, instance_id, object_id) VALUES (' \"/usr/local/icinga2/etc/icinga2/scripts/mail-service-notification.sh\"', '1', 1, 51424)
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_customvariablestatus WHERE session_token <> 1470932597


[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: UPDATE icinga_objects SET is_active = 1 WHERE object_id = 51421
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: UPDATE icinga_objects SET is_active = 1 WHERE object_id = 51422
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: UPDATE icinga_objects SET is_active = 1 WHERE object_id = 51423
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: UPDATE icinga_objects SET is_active = 1 WHERE object_id = 51424
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: UPDATE icinga_objects SET is_active = 1 WHERE object_id = 190
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: UPDATE icinga_objects SET is_active = 1 WHERE object_id = 188
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: UPDATE icinga_objects SET is_active = 1 WHERE object_id = 187
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: COMMIT
[2016-08-11 18:24:36 +0200] debug/IdoMysqlConnection: Query: BEGIN
[2016-08-11 18:24:37 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_programstatus WHERE instance_id = 1
[2016-08-11 18:24:37 +0200] debug/IdoMysqlConnection: Query: INSERT INTO icinga_programstatus (active_host_checks_enabled, active_service_checks_enabled, daemon_mode, endpoint_name, event_handlers_enabled, flap_detection_enabled, instance_id, is_currently_running, last_co
mmand_check, notifications_enabled, passive_host_checks_enabled, passive_service_checks_enabled, process_id, process_performance_data, program_start_time, program_version, status_update_time) VALUES ('0', '0', '1', 'mbmif.int.netways.de', '1', '1', 1, '1', FROM_UNIXTIME(1
470932677), '1', '1', '1', '72784', '1', FROM_UNIXTIME(1470932586), 'v2.4.10', FROM_UNIXTIME(1470932677))

2.5.0

v2.4.10-639-gb3f4a4d

77 seconds.

[2016-08-11 18:03:11 +0200] debug/IdoMysqlConnection: Query: SELECT @@global.max_allowed_packet AS max_allowed_packet
...
[2016-08-11 18:04:28 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_customvariables WHERE instance_id = 1 AND session_token <> 1470931382
[2016-08-11 18:04:28 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_customvariablestatus WHERE instance_id = 1 AND session_token <> 1470931382
[2016-08-11 18:04:28 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_hostgroup_members WHERE instance_id = 1 AND session_token <> 1470931382
[2016-08-11 18:04:28 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_servicegroup_members WHERE instance_id = 1 AND session_token <> 1470931382
[2016-08-11 18:04:28 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_contactgroup_members WHERE instance_id = 1 AND session_token <> 1470931382
[2016-08-11 18:04:28 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_comments WHERE instance_id = 1 AND session_token <> 1470931382
[2016-08-11 18:04:28 +0200] debug/IdoMysqlConnection: Query: DELETE FROM icinga_scheduleddowntime WHERE instance_id = 1 AND session_token <> 1470931382

Conclusio

The IDO config dump is nearly the same. 2.4.10 has several bugs with query priority ordering which might cause custom vars not being deleted, or the wrong assumption of the finished config dump while it actually isn't.

While this issue helped to nail down the initial query differences, after all there is no noticeable performance drop. But it is the same or a bit faster even. I'm attaching the gzipped debug logs in case you're interested.

I'm therefore closing the issue.

icinga-migration · 2016-08-16T17:43:10Z

Updated by hvhaugwitz on 2016-08-16 17:43:10 +00:00

I'm a bit surprised that you closed this bug report without asking for feedback,
just because your specific use case performs well on your test setup.

But nevertheless the recent commits from gunnarbeutner fixing #12435 also fixed
this issue. The reload performance improved from 208s with v2.4.10-650-ge28f30a
to 20s with v684-ga34e01d . That's awesome. Many thanks for this.

icinga-migration · 2016-08-16T18:19:33Z

Updated by mfriedrich on 2016-08-16 18:19:33 +00:00

You've built your arguments based on assumptions with the log entries. I already mentioned that this method doesn't work.

Of course I could have asked for a more in-depth analysis on your side. I just felt that this isn't necessary as I did not recognise any specific performance decreasements in other test environments.

Sorry if that came out the wrong way. I appreciate what you and others do with testing and additional help in making the next release great.

icinga-migration closed this as completed Aug 11, 2016

icinga-migration added bug Something isn't working area/db-ido Database output labels Jan 17, 2017

icinga-migration added this to the 2.5.0 milestone Jan 17, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[dev.icinga.com #12258] icinga2 IDO reload performance significant slower with latest snapshot release #4418

[dev.icinga.com #12258] icinga2 IDO reload performance significant slower with latest snapshot release #4418

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 30, 2016

icinga-migration commented Aug 1, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 3, 2016

icinga-migration commented Aug 3, 2016

icinga-migration commented Aug 3, 2016

icinga-migration commented Aug 8, 2016

icinga-migration commented Aug 11, 2016

icinga-migration commented Aug 16, 2016

icinga-migration commented Aug 16, 2016

[dev.icinga.com #12258] icinga2 IDO reload performance significant slower with latest snapshot release #4418

[dev.icinga.com #12258] icinga2 IDO reload performance significant slower with latest snapshot release #4418

Comments

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 29, 2016

icinga-migration commented Jul 30, 2016

icinga-migration commented Aug 1, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 2, 2016

icinga-migration commented Aug 3, 2016

icinga-migration commented Aug 3, 2016

icinga-migration commented Aug 3, 2016

icinga-migration commented Aug 8, 2016

icinga-migration commented Aug 11, 2016

Steps to reproduce

Test environment

2.4.10

2.5.0

Conclusio

icinga-migration commented Aug 16, 2016

icinga-migration commented Aug 16, 2016