Details

    • Type: Bug
    • Status: Closed
    • Priority: Normal
    • Resolution: Fixed
    • Affects Version/s: PDB 2.2.2
    • Fix Version/s: None
    • Component/s: None
    • Labels:
    • Template:

      Description

      Greetings,

      We faced into issues with PuppetDB PostgreSQL processes using all cores on our Puppet Master server (LA = 100 with 32 cores).
      This server have following components installed:
      1. puppet-server 3.7.3 (httpd with passenger)
      2. PuppetDB 2.2.2 with PostgreSQL 9.3

      This is master sever from master-slave PostgreSQL replication setup using PuppetDB database and read-database settings.

      Issues was solved by following this instruction:
      https://docs.puppetlabs.com/puppetdb/latest/trouble_kahadb_corruption.html
      on all PuppetDB nodes and repeated one more time in approximately a week.

      top was showing a lot of DELETE PostgreSQL queries.

      Following queries were in blocked state in PostgreSQL:

      -[ RECORD 1 ]------+------------------------------------------------------------------------------------------------------------------------------------------
      ------------------------------
      blocked_pid        | 17367
      blocked_user       | puppetdb
      blocking_pid       | 14736
      blocking_user      | puppetdb
      blocked_statement  | UPDATE certnames SET deactivated=$1 WHERE name=$2 AND (deactivated<$3 OR deactivated IS NULL)
      blocking_statement | DELETE FROM fact_paths fp
                         |                                       WHERE fp.id in ( SELECT fp.id
                         |                                                        FROM fact_paths fp
                         |                                                             inner join fact_values fv on fp.id = fv.path_id
                         |                                                             inner join facts f on fv.id = f.fact_value_id
                         |                                                        WHERE fp.id in ( select fv.path_id from fact_values fv where fv.id in ($1,$2,$3,$4,$5) )
                         |                                                        GROUP BY fp.id
                         |                                                        HAVING COUNT(fv.id) = 1)
      -[ RECORD 2 ]------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------
      blocked_pid        | 19100
      blocked_user       | puppetdb
      blocking_pid       | 11406
      blocking_user      | puppetdb
      blocked_statement  | UPDATE certnames SET deactivated=$1 WHERE name=$2 AND (deactivated<$3 OR deactivated IS NULL)
      blocking_statement | DELETE FROM fact_paths fp
                         |                                       WHERE fp.id in ( SELECT fp.id
                         |                                                        FROM fact_paths fp
                         |                                                             inner join fact_values fv on fp.id = fv.path_id
                         |                                                             inner join facts f on fv.id = f.fact_value_id
                         |                                                        WHERE fp.id in ( select fv.path_id from fact_values fv where fv.id in ($1,$2,$3,$4) )
                         |                                                        GROUP BY fp.id
      
      

      postgres 15706  0.0  0.0 1308216 3044 ?        Ss   Jan14   4:53 postgres: wal sender process replicator 10.138.2.254(42132) streaming 23B/6509E000
      postgres 15781  2.9  0.0 1313648 231772 ?      Ss   12:32   0:50 postgres: puppetdb puppetdb 10.154.18.254(21185) idle
      postgres 15782  3.0  0.0 1313664 227856 ?      Ss   12:32   0:54 postgres: puppetdb puppetdb 10.169.2.254(48139) idle
      postgres 15797  2.9  0.0 1314616 249512 ?      Ss   12:32   0:52 postgres: puppetdb puppetdb 10.154.18.254(21189) DELETE
      postgres 15798  2.1  0.0 1315100 215992 ?      Ss   12:32   0:38 postgres: puppetdb puppetdb 10.142.2.254(64121) idle
      postgres 15803  5.0  0.0 1325240 293824 ?      Ss   12:32   1:29 postgres: puppetdb puppetdb 10.138.2.254(30178) DELETE
      postgres 15804  3.7  0.0 1326772 299284 ?      Ss   12:32   1:06 postgres: puppetdb puppetdb 10.138.2.254(30180) idle
      postgres 15805  1.1  0.0 1321760 230456 ?      Rs   12:32   0:20 postgres: puppetdb puppetdb 10.142.2.254(64122) DELETE
      postgres 15806  3.9  0.0 1325596 289632 ?      Ss   12:32   1:09 postgres: puppetdb puppetdb 10.138.2.254(30181) idle
      postgres 15807  2.7  0.0 1315248 229400 ?      Ss   12:32   0:48 postgres: puppetdb puppetdb 10.169.2.254(48142) UPDATE waiting
      postgres 15808  3.0  0.0 1322712 238792 ?      Ss   12:32   0:53 postgres: puppetdb puppetdb 10.154.18.254(21190) idle
      postgres 15809  2.2  0.0 1324752 295480 ?      Ss   12:32   0:40 postgres: puppetdb puppetdb 10.138.2.254(30183) UPDATE waiting
      postgres 15810  0.5  0.0 1317340 240840 ?      Ss   12:32   0:08 postgres: puppetdb puppetdb 10.142.2.254(64124) idle
      postgres 15811  3.2  0.0 1324280 297624 ?      Ss   12:32   0:56 postgres: puppetdb puppetdb 10.138.2.254(30185) idle
      postgres 15812  4.7  0.0 1327552 314488 ?      Ss   12:32   1:22 postgres: puppetdb puppetdb 10.138.2.254(30187) DELETE
      postgres 15819  0.5  0.0 1313504 217788 ?      Ss   12:32   0:09 postgres: puppetdb puppetdb 10.142.2.254(64125) idle
      postgres 15820  2.6  0.0 1315084 255340 ?      Ss   12:32   0:46 postgres: puppetdb puppetdb 10.154.18.254(21193) UPDATE waiting
      postgres 15821  3.4  0.0 1324264 314948 ?      Ss   12:32   1:01 postgres: puppetdb puppetdb 10.138.2.254(30189) idle
      postgres 15829  4.7  0.2 1316500 854736 ?      Rs   12:32   1:22 postgres: puppetdb puppetdb 10.138.2.254(30192) DELETE
      postgres 15831  0.5  0.0 1322468 221836 ?      Rs   12:32   0:09 postgres: puppetdb puppetdb 10.142.2.254(64127) DELETE
      postgres 15832  2.9  0.0 1314600 227644 ?      Rs   12:32   0:52 postgres: puppetdb puppetdb 10.169.2.254(48143) DELETE
      postgres 15834  4.6  0.2 1316500 831668 ?      Ss   12:32   1:21 postgres: puppetdb puppetdb 10.154.18.254(21194) UPDATE waiting
      postgres 15836  1.7  0.0 1322444 228392 ?      Ss   12:32   0:30 postgres: puppetdb puppetdb 10.142.2.254(64129) idle
      postgres 15843  3.2  0.0 1316476 234668 ?      Ss   12:32   0:57 postgres: puppetdb puppetdb 10.154.18.254(21197) idle
      postgres 15847  1.4  0.0 1313984 228368 ?      Rs   12:32   0:25 postgres: puppetdb puppetdb 10.169.2.254(48145) DELETE
      postgres 15859  2.4  0.2 1320824 830472 ?      Ss   12:32   0:43 postgres: puppetdb puppetdb 10.142.2.254(64136) idle
      postgres 15875  0.4  0.0 1313444 212256 ?      Ss   12:32   0:08 postgres: puppetdb puppetdb 10.142.2.254(64138) UPDATE waiting
      postgres 15880  1.1  0.0 1315056 241040 ?      Ss   12:32   0:20 postgres: puppetdb puppetdb 10.169.2.254(48149) idle
      postgres 15886  0.5  0.0 1313600 220652 ?      Ss   12:32   0:09 postgres: puppetdb puppetdb 10.142.2.254(64141) idle
      postgres 15887  0.5  0.0 1319640 241572 ?      Ss   12:32   0:09 postgres: puppetdb puppetdb 10.142.2.254(64142) idle
      postgres 15888  3.7  0.0 1313988 240988 ?      Ss   12:32   1:06 postgres: puppetdb puppetdb 10.169.2.254(48151) idle
      postgres 15896  1.8  0.0 1321144 248224 ?      Ss   12:32   0:32 postgres: puppetdb puppetdb 10.144.2.254(46747) idle
      postgres 15938  0.9  0.0 1314332 227196 ?      Ss   12:32   0:16 postgres: puppetdb puppetdb 10.169.2.254(48161) UPDATE waiting
      postgres 15970  3.0  0.2 1314380 844188 ?      Ss   12:32   0:53 postgres: puppetdb puppetdb 10.169.2.254(48163) idle
      postgres 15989  4.1  0.0 1316776 242280 ?      Ss   12:32   1:11 postgres: puppetdb puppetdb 10.154.18.254(21221) idle in transaction
      postgres 15999  2.9  0.0 1313764 233620 ?      Ss   12:32   0:51 postgres: puppetdb puppetdb 10.154.18.254(21226) idle
      postgres 16025  2.6  0.0 1314980 238856 ?      Ss   12:32   0:45 postgres: puppetdb puppetdb 10.169.2.254(48176) INSERT waiting
      postgres 16048  2.3  0.0 1313940 228432 ?      Rs   12:32   0:40 postgres: puppetdb puppetdb 10.169.2.254(48178) DELETE
      postgres 16119  2.8  0.0 1323948 251956 ?      Ss   12:33   0:48 postgres: puppetdb puppetdb 10.154.18.254(21267) idle
      postgres 16134  1.1  0.0 1314784 232388 ?      Ss   12:33   0:20 postgres: puppetdb puppetdb 10.154.18.254(21271) UPDATE waiting
      postgres 16186  2.4  0.0 1313968 228904 ?      Ss   12:33   0:43 postgres: puppetdb puppetdb 10.154.18.254(21285) UPDATE waiting
      

      UPDATE:
      It happend again after a few hours.
      Messages in puppetdb.log

      2015-01-19 13:34:23,122 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-7:1:1 Transaction Commit :null
      2015-01-19 13:34:23,241 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-9:1:1 Transaction Commit :null
      2015-01-19 13:34:23,318 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-8:1:1 Transaction Commit :null
      2015-01-19 13:34:23,374 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-13:1:1 Transaction Commit :null
      2015-01-19 13:34:23,379 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-20:1:1 Transaction Commit :null
      2015-01-19 13:34:23,429 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-35:1:1 Transaction Commit :null
      2015-01-19 13:34:23,707 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-19:1:1 Transaction Commit :null
      2015-01-19 13:34:23,748 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-24:1:1 Transaction Commit :null
      2015-01-19 13:34:23,826 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-26:1:1 Transaction Commit :null
      2015-01-19 13:34:23,828 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-29:1:1 Transaction Commit :null
      2015-01-19 13:34:23,842 DEBUG [o.a.a.ActiveMQSession] ID:myhost.net-13102-1421657251640-17:1:1 Transaction Commit :null
      

        Attachments

          Issue Links

            Activity

              jsd-sla-details-panel

                People

                • Assignee:
                  Unassigned
                  Reporter:
                  a_fomenko Anton Fomenko
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: