PostgreSQL La base de donnees la plus sophistiquee au monde.

Forums PostgreSQL.fr

Le forum officiel de la communauté francophone de PostgreSQL

Vous n'êtes pas identifié(e).

#1 23/01/2013 15:18:22

mortimer.pw
Membre

Que fait la requête ?

Bonjour à tous,

Je travaille sur une base en 8.4.2 sous CentOS 5.4.

Sous linux, je vois les process ci-dessous :
          postgres 12755  3507  0 15:10 ?        00:00:24 postgres: pointage geo 19.168.2.14(1117) SELECT         
          postgres 16147  3507  0 15:21 ?        00:00:24 postgres: pointage geo 19.168.2.14(1107) SELECT         
          postgres 16374  3507  0 15:24 ?        00:00:24 postgres: pointage geo 19.168.2.14(1291) SELECT         

Sous psql, lorsque je fais un select * from pg_stat_activity, je vois :
           16384 | geo     |   16147 |    20978 | pointage | SELECT   | f       | 2013-01-23 15:21:42.358439+03 | 2013-01-23 15:21:42.358439+03 | 2013-01-23 15:21:34.756382+03 | 19.168.2.14 |        1107
           16384 | geo     |   12755 |    20978 | pointage | SELECT   | f       | 2013-01-23 15:10:13.670896+03 | 2013-01-23 15:10:13.670896+03 | 2013-01-23 15:10:01.648317+03 | 19.168.2.14 |        1117
           16384 | geo     |   16374 |    20978 | pointage | SELECT  | f       | 2013-01-23 15:24:46.351679+03 | 2013-01-23 15:24:46.351679+03 | 2013-01-23 15:24:40.632286+03 | 19.168.2.14 |        1291

Comment savoir si les requêtes sont réellement en cours ?

Merci pour votre aide.

Dernière modification par mortimer.pw (24/01/2013 09:21:09)

Hors ligne

#2 23/01/2013 15:42:16

gleu
Administrateur

Re : Que fait la requête ?

Elles sont réellement en cours d'exécution, vu que la colonne qui contient 'f' doit être la colonne waiting, et donc que les processus ne sont pas en attente d'un verrou.


Guillaume.

Hors ligne

#3 24/01/2013 09:18:51

mortimer.pw
Membre

Re : Que fait la requête ?

Hier soir, suite à nos remarques sur des requêtes visiblement trés longues, nous avons décidé de programmer un "vacuumdb -a -f -z" à 01h30 du matin.

Ce matin à partir de 06h00, les opérateurs commencent leur journée de travail et accédent à la base de données.

Entre 06h00 et 07h30, nous avons des messages dans les logs :
    19.168.2.72 19352 2013-01-24 07:31:24 EAT startup 1 FATAL:  connection limit exceeded for non-superusers
    19.168.2.72 19353 2013-01-24 07:31:24 EAT startup 1 FATAL:  connection limit exceeded for non-superusers
    19.168.2.72 19354 2013-01-24 07:31:24 EAT startup 1 FATAL:  connection limit exceeded for non-superusers
    19.168.2.72 19355 2013-01-24 07:31:24 EAT startup 1 FATAL:  connection limit exceeded for non-superusers
    19.168.2.72 19356 2013-01-24 07:31:25 EAT startup 1 FATAL:  connection limit exceeded for non-superusers
   
A 07h33, les logs suivants.
Un technicien à killé une connexion cliente :
    19.168.3.198 19482 2013-01-24 07:33:37 EAT startup 1 FATAL:  connection limit exceeded for non-superusers
        3507 2013-01-24 07:33:58 EAT  2 LOG:  server process (PID 29082) was terminated by signal 9: Killed
        3507 2013-01-24 07:33:58 EAT  3 LOG:  terminating any other active server processes
    19.168.3.93 3851 2013-01-24 07:33:58 EAT SELECT waiting 3 WARNING:  terminating connection because of crash of another server process at character 15
    19.168.3.93 3851 2013-01-24 07:33:58 EAT SELECT waiting 4 DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
    19.168.3.93 3851 2013-01-24 07:33:58 EAT SELECT waiting 5 HINT:  In a moment you should be able to reconnect to the database and repeat your command.

    [local] 20448 2013-01-24 07:33:58 EAT VACUUM waiting 2 WARNING:  terminating connection because of crash of another server process
    [local] 20448 2013-01-24 07:33:58 EAT VACUUM waiting 3 DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
    [local] 20448 2013-01-24 07:33:58 EAT VACUUM waiting 4 HINT:  In a moment you should be able to reconnect to the database and repeat your command.

        3507 2013-01-24 07:33:59 EAT  4 LOG:  all server processes terminated; reinitializing
    127.0.0.1 19505 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
    127.0.0.1 19507 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
    127.0.0.1 19511 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
    127.0.0.1 19512 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
        19504 2013-01-24 07:33:59 EAT  1 LOG:  database system was interrupted; last known up at 2013-01-24 06:04:54 EAT
    127.0.0.1 19510 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
    127.0.0.1 19509 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
    127.0.0.1 19570 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
        19504 2013-01-24 07:33:59 EAT  2 LOG:  database system was not properly shut down; automatic recovery in progress
    127.0.0.1 19574 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
    19.168.2.154 19582 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
        19504 2013-01-24 07:33:59 EAT  3 LOG:  redo starts at 330/FBECF0F8
    127.0.0.1 19583 2013-01-24 07:33:59 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
    19.168.2.77 19649 2013-01-24 07:34:00 EAT /usr/local/pgsql/bin/postmaster 1 FATAL:  the database system is in recovery mode
        19653 2013-01-24 07:34:00 EAT  1 LOG:  autovacuum launcher started
        3507 2013-01-24 07:34:00 EAT  5 LOG:  database system is ready to accept connections

La base est repartie, mais le vacuum n'est pas fait et toutes les connexions sont réinitialisés.

Pouvez-vous me dire, si killer un processus client, est une erreur ? dans ce cas quelle est la bonne manière d'arrêter un client ?
Est-ce bien la raison de la fermeture de toutes les connexions ? et du redémarrage de la base ?
Le vacuum bloque t'il les connexions (connection limit exceeded for non-superusers) ?

Merci pour votre support.

Dernière modification par mortimer.pw (24/01/2013 09:23:37)

Hors ligne

#4 24/01/2013 10:47:19

rjuju
Administrateur

Re : Que fait la requête ?

Bonjour,

vous avez utilisé l'option -f qui fait un vacuum full, ce qui nécessite un verrou exclusif sur les tables. Selon la volumétrie de la base, les requêtes ont été mise en attente plus ou moins longtemps.


Un kill de processus n'est pas du tout recommandable, et c'est bien lui qui est la cause du redémarrage. Si vous êtes en version 8.4 ou supérieur, vous pouvez utiliser la fonction pg_terminate_backend qui stoppera proprement une connexion. Il est en général préférable d'analyser la situation, par exemple pour voir si une requête bloque d'autres requêtes.

Hors ligne

#5 24/01/2013 12:08:19

mortimer.pw
Membre

Re : Que fait la requête ?

Bonjour Julien,

Merci pour les infos.

Il semble qu'une seule table nous pénalise, ci-dessous sa définition :

CREATE TABLE ptg_pers
(
  id serial NOT NULL,
  id_perso character varying(8),
  id_ligne character varying(4),
  id_plan character varying(4),
  id_fonction character varying(4),
  id_operation character varying(4),
  ofp_cpt character varying(10),
  ofs_cpt character varying(10),
  id_document character varying(150),
  jour date,
  heure_deb character(6),
  heure_fin character(6),
  temps numeric(7,4),
  quantite numeric,
  id_type_trt_ptg character varying(2) NOT NULL DEFAULT 'NV'::character varying,
  lib_err character varying(200),
  id_job character varying(150) NOT NULL DEFAULT '0'::character varying,
  id_type_ptg_sst character varying(1) NOT NULL DEFAULT 'G'::character varying,
  date_fin date,
  refection numeric(1,0) NOT NULL DEFAULT 0,
  test numeric(1,0) NOT NULL DEFAULT 0,
  CONSTRAINT pk_ptg_pers PRIMARY KEY (id),
  CONSTRAINT fk_ptg_pers_fonction FOREIGN KEY (id_fonction) REFERENCES fonction (id_fonction) MATCH SIMPLE ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT fk_ptg_pers_ligne FOREIGN KEY (id_ligne) REFERENCES ligne (id_ligne) MATCH SIMPLE ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT fk_ptg_pers_operation FOREIGN KEY (id_operation) REFERENCES operation (id_operation) MATCH SIMPLE ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT fk_ptg_pers_plan FOREIGN KEY (id_plan) REFERENCES plan (id_plan) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT fk_ptg_pers_type_ptg_sst FOREIGN KEY (id_type_ptg_sst) REFERENCES type_ptg_sst (id_type_ptg_sst) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT fk_ptg_pers_type_trt_ptg FOREIGN KEY (id_type_trt_ptg) REFERENCES type_etat (id_type_etat) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION
)
WITH (OIDS=FALSE);
ALTER TABLE ptg_pers OWNER TO postgres;
GRANT ALL ON TABLE ptg_pers TO postgres;
GRANT SELECT ON TABLE ptg_pers TO basic_geo;
GRANT UPDATE, INSERT, DELETE ON TABLE ptg_pers TO maj_alimgeo;
GRANT UPDATE, INSERT, DELETE ON TABLE ptg_pers TO maj_pointage;
GRANT UPDATE, INSERT ON TABLE ptg_pers TO maj_geo;
GRANT DELETE ON TABLE ptg_pers TO adm_geo;
GRANT SELECT, UPDATE, INSERT ON TABLE ptg_pers TO basic_sas;

-- Index: ptg_pers_idx
CREATE INDEX ptg_pers_idx ON ptg_pers USING btree(id_ligne, id_plan, id_fonction, id_document, id_job, id_type_trt_ptg, id_type_ptg_sst);
-- Index: ptg_pers_idx1
CREATE INDEX ptg_pers_idx1 ON ptg_pers USING btree(id_ligne, id_plan, id_fonction, id_operation, ofp_cpt, jour, id_type_trt_ptg, id_type_ptg_sst, id_job, id_document);

-- Index: ptg_pers_idx2
CREATE INDEX ptg_pers_idx2 ON ptg_pers USING btree (id_type_ptg_sst, id_job, id_document, id_ligne, id_plan, id_fonction);

-- Index: ptg_pers_idx3
CREATE INDEX ptg_pers_idx3 ON ptg_pers USING btree(id_ligne, id_plan, id_fonction, id_job);

-- Index: ptg_pers_jour_type_ptg_sst
CREATE INDEX ptg_pers_jour_type_ptg_sst ON ptg_pers USING btree(jour, id_type_trt_ptg);

-- Index: ptg_pers_jour_type_ptg_sst_type_trt_ptg
CREATE INDEX ptg_pers_jour_type_ptg_sst_type_trt_ptg ON ptg_pers USING btree(jour, id_type_ptg_sst, id_type_trt_ptg);

-- Trigger: jt_ptg_pers on ptg_pers
CREATE TRIGGER jt_ptg_pers AFTER INSERT OR UPDATE ON ptg_pers FOR EACH ROW EXECUTE PROCEDURE j_geo.jf_ptg_pers();


Elle contient 15 millions d'enregistrements.

Une vingtaine d'utilisateurs, font des requêtes sur cette table, où ils récupérent des données par jour (donné en paramètre).

Depuis 2 jours, nous faisons de la mise à jour, par soft JAVA, avec en paramètre les champs JOUR et TYPE_PTG_SST. En moyenne 30000 lignes sont traitées.
La première requête demande le min(jour) pour savoir sur quelle journée faire le traitement.
Ensuite, le TYPE_PTG_SST est modifié puis les données sont journalisées dans une autre table (que certains champs).
Ensuite les données journalisées et les données de cette table sont croisées, puis transférées sur une autre base.
Finalement les données de PTG_PERS sont updatées (champ ID_TYPE_PTG_SST) et les données journalisées supprimées.

Parfois la première requête répond dans la seconde, parfois en plus d'une minute.
L'ensemble des select sur cette table sont lents.

Est-ce que le nombre important de modifications de lignes peut causer ces ralentissements ? des problèmes de statistiques ? d'écriture de logs ? d'I/O ?

Je m'excuse si l'explication est un peu longue, et encore merci pour votre participation.

Hors ligne

#6 24/01/2013 12:17:10

gleu
Administrateur

Re : Que fait la requête ?

30000 lignes traitées par jour, ce n'est strictement rien. Les ralentissements que vous évoquez peuvent être dûs à tous les points que vous citez : problèmes de statistiques qui font que les plans générés ne sont pas bons, écritures sur disque, bande passante trop forte. Il peut y avoir beaucoup d'autres problèmes.

Il me semble, avant toute chose, que le mieux serait de tracer les requêtes exécutées par PostgreSQL (par exemple avec un log_min_duration_statement à 0), puis d'analyser les logs avec un outil comme pgbadger. Cela permettra de voir un peu mieux les requêtes qui prennent du temps sur votre système.


Guillaume.

Hors ligne

#7 24/01/2013 12:53:15

mortimer.pw
Membre

Re : Que fait la requête ?

Bonjour guillaume,

Ci-dessous la requête exécutée par la vingtaine d'utilisateurs. Ils exécutent cette requête chaque jour, pour faire de la validation/correction de données.

SELECT PTG.ID,PTG.ID_PERSO, PTG.ID_LIGNE, PTG.ID_PLAN, PTG.ID_FONCTION, PTG.ID_OPERATION, PTG.OFP_CPT, PTG.OFS_CPT, PTG.ID_DOCUMENT, PTG.JOUR, PTG.HEURE_DEB, PTG.HEURE_FIN, PTG.TEMPS, PTG.QUANTITE, PTG.ID_TYPE_TRT_PTG, PTG.LIB_ERR, PE.NOM, PE.PRENOM, PE.LIGNE_DEFAUT, PE.ID_TYPE_OPER, LI.LIBELLE, PL.LIBELLE, FO.LIBELLE, OP.LIBELLE, OP.ID_TYPE_ALIM, AC.id_type_act, AC.CODE_COMPTA FROM geo.ptg_pers PTG, geo.PERSONNEL PE, geo.LIGNE LI, geo.PLAN PL, geo.FONCTION FO, geo.OPERATION OP, geo.ACTIVITE AC WHERE (PTG.JOUR=TO_DATE('20130123','YYYYMMDD')) AND PTG.ID_TYPE_PTG_SST='G' AND PTG.ID_PERSO=PE.ID_PERSO AND PE.ID_GROUPE='00008' AND PTG.ID_LIGNE=LI.ID_LIGNE AND PTG.ID_PLAN=PL.ID_PLAN AND PTG.ID_FONCTION=FO.ID_FONCTION AND PTG.ID_OPERATION=OP.ID_OPERATION AND AC.id_ligne = PTG.id_ligne AND AC.id_plan = PTG.id_plan AND AC.id_fonction = PTG.id_fonction AND AC.id_operation = PTG.id_operation AND AC.DATE_FIN_VALIDE=(SELECT min(AC2.DATE_FIN_VALIDE) from geo.ACTIVITE AC2 WHERE AC2.id_ligne = AC.id_ligne AND AC2.id_plan = AC.id_plan AND AC2.id_fonction = AC.id_fonction AND AC2.id_operation = AC.id_operation AND AC2.DATE_FIN_VALIDE>=TO_DATE('20130123','YYYYMMDD')) ORDER BY PTG.ID_PERSO, PTG.HEURE_DEB, PTG.HEURE_FIN

Ci-dessous, les requêtes du soft JAVA :

parti pour déclencher la journalisation:
select to_char(min(jour),'yyyymmdd') from geo.ptg_pers where id_type_ptg_sst='G';
update geo.ptg_pers set id_ligne='0'||substr(id_ligne,2,2) where jour=to_date('+MinJOUR+','YYYYMMDD') and id_type_ptg_sst='G' and substr(id_ligne,1,1)!='0' and id_ligne not in ('289','295');
update geo."ptg_pers set id_type_trt_ptg='OK',id_type_ptg_sst='S' where jour=to_date('+MinJOUR+','YYYYMMDD') and id_type_ptg_sst='G'";
-->insert dans j_geo.j_ptg_pers via trigger

parti pour transférer les données sur l'autre base
select TO_CHAR(CAST(NOW() AS TIMESTAMP without time zone),'YYYYMMDDHH24MISS')
update "+ptrStep.getM_J_Table_NAME()+" set j_consumed='1' where id_site='"+m_ConnexBase_GEO_LOCAL.getM_SITE()+"' and j_consumed!='2' and j_date<to_timestamp('"+m_TIMESTAMP+"','yyyymmddHH24MISS')
select j.id_site,j.id,id_perso,id_ligne,id_plan,id_fonction,id_operation,ofp_cpt,ofs_cpt,id_document,to_char(jour,'yyyymmdd')
,heure_deb,heure_fin,temps,quantite,id_type_trt_ptg,id_job,id_type_ptg_sst,to_char(date_fin,'yyyymmdd'),refection,test
from ( SELECT l.id_site, l.id, max(l.j_date) AS j_date FROM j_jeo.j_ptg_pers l WHERE l.j_consumed='1' GROUP BY l.id_site, l.id) j
LEFT JOIN geo.ptg_pers targ ON j.id= targ.id order by j_date

Ci-dessous, des extractions statistiques faites hier à 17h. Attention le serveur a redémarré hier entre 12 et 13 heures :

geo=# select * from pg_stat_database;
datid |  datname  | numbackends | xact_commit | xact_rollback | blks_read | blks_hit  | tup_returned | tup_fetched | tup_inserted | tup_updated | tup_deleted
-------+-----------+-------------+-------------+---------------+-----------+-----------+--------------+-------------+--------------+-------------+-------------
     1 | template1 |           0 |           0 |             0 |         0 |         0 |            0 |           0 |            0 |           0 |           0
11563 | template0 |           0 |           0 |             0 |         0 |         0 |            0 |           0 |            0 |           0 |           0
11564 | postgres  |           0 |           0 |             0 |         0 |         0 |            0 |           0 |            0 |           0 |           0
16384 | geo       |          30 |       90940 |           235 |  20624797 | 117631459 |   1234857883 |    55114244 |       357285 |     1295003 |      326562
(4 rows)


geo=# select * from pg_stat_bgwriter;
checkpoints_timed | checkpoints_req | buffers_checkpoint | buffers_clean | maxwritten_clean | buffers_backend | buffers_alloc
-------------------+-----------------+--------------------+---------------+------------------+-----------------+---------------
                66 |               0 |             105629 |        173413 |              163 |           24438 |      13626495
(1 row)


geo=# SELECT seq_scan,seq_tup_read,idx_scan,idx_tup_fetch,n_tup_ins,n_tup_upd,n_tup_del,last_autovacuum,last_autoanalyze FROM pg_stat_all_tables WHERE schemaname='geo' and relname='ptg_pers';
seq_scan | seq_tup_read | idx_scan | idx_tup_fetch | n_tup_ins | n_tup_upd | n_tup_del | last_autovacuum | last_autoanalyze
----------+--------------+----------+---------------+-----------+-----------+-----------+-----------------+------------------
       50 |    579565567 |   480956 |      32931299 |     10604 |    636226 |         3 |                 |
(1 row)


geo=# SELECT idx_scan,idx_tup_read,idx_tup_fetch FROM pg_stat_all_indexes WHERE schemaname='geo' and relname='ptg_pers' and indexrelname='ptg_pers_jour_type_ptg_sst_type_trt_ptg';
idx_scan | idx_tup_read | idx_tup_fetch
----------+--------------+---------------
      330 |      9532328 |        863153
(1 row)


geo=# SELECT idx_scan,idx_tup_read,idx_tup_fetch FROM pg_stat_all_indexes WHERE schemaname='geo' and relname='ptg_pers' and indexrelname='ptg_pers_idx';
idx_scan | idx_tup_read | idx_tup_fetch
----------+--------------+---------------
    16541 |     12049901 |      12026279
(1 row)


geo=# SELECT idx_scan,idx_tup_read,idx_tup_fetch FROM pg_stat_all_indexes WHERE schemaname='geo' and relname='ptg_pers' and indexrelname='ptg_pers_idx1';
idx_scan | idx_tup_read | idx_tup_fetch
----------+--------------+---------------
   146365 |      7205857 |       6759342
(1 row)


geo=# SELECT idx_scan,idx_tup_read,idx_tup_fetch FROM pg_stat_all_indexes WHERE schemaname='geo' and relname='ptg_pers' and indexrelname='ptg_pers_idx2';
idx_scan | idx_tup_read | idx_tup_fetch
----------+--------------+---------------
        0 |            0 |             0
(1 row)


geo=# SELECT idx_scan,idx_tup_read,idx_tup_fetch FROM pg_stat_all_indexes WHERE schemaname='geo' and relname='ptg_pers' and indexrelname='ptg_pers_idx3';
idx_scan | idx_tup_read | idx_tup_fetch
----------+--------------+---------------
       59 |       899041 |        887892
(1 row)


geo=# SELECT idx_scan,idx_tup_read,idx_tup_fetch FROM pg_stat_all_indexes WHERE schemaname='geo' and relname='ptg_pers' and indexrelname='ptg_pers_jour_type_ptg_sst';
idx_scan | idx_tup_read | idx_tup_fetch
----------+--------------+---------------
       71 |      6566273 |       5653069
(1 row)


geo=# SELECT idx_scan,idx_tup_read,idx_tup_fetch FROM pg_stat_all_indexes WHERE schemaname='geo' and relname='ptg_pers' and indexrelname='pk_ptg_pers';
idx_scan | idx_tup_read | idx_tup_fetch
----------+--------------+---------------
   317735 |       953162 |        317732
(1 row)


geo=# select * from pg_statio_user_tables WHERE schemaname='geo' and relname='ptg_pers';
relid | schemaname | relname  | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit
-------+------------+----------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
16643 | geo        | ptg_pers |       15051277 |      23997829 |       5053672 |     28331588 |               0 |              0 |              0 |             0
(1 row)


geo=# select * from pg_statio_user_indexes WHERE schemaname='geo' and relname='ptg_pers';
relid | indexrelid | schemaname | relname  |              indexrelname               | idx_blks_read | idx_blks_hit
-------+------------+------------+----------+-----------------------------------------+---------------+--------------
16643 |    2278788 | geo        | ptg_pers | ptg_pers_jour_type_ptg_sst_type_trt_ptg |        823753 |      2982737
16643 |      16794 | geo        | ptg_pers | pk_ptg_pers                             |          5476 |      2906239
16643 |      17232 | geo        | ptg_pers | ptg_pers_idx                            |       1719014 |      9991085
16643 |      17233 | geo        | ptg_pers | ptg_pers_idx1                           |       1999807 |      4068897
16643 |      17234 | geo        | ptg_pers | ptg_pers_idx2                           |         54357 |      3262287
16643 |      17235 | geo        | ptg_pers | ptg_pers_idx3                           |         19507 |      2841631
16643 |      17236 | geo        | ptg_pers | ptg_pers_jour_type_ptg_sst              |        431758 |      2278712
(7 rows)

L'exécution d'une commande TOP sur la machine :

top - 13:47:20 up 23:13,  3 users,  load average: 3.48, 3.77, 3.53
Tasks: 242 total,   2 running, 240 sleeping,   0 stopped,   0 zombie
Cpu(s):  1.8%us,  0.3%sy,  0.0%ni, 83.4%id, 14.4%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4046316k total,  4020748k used,    25568k free,    20296k buffers
Swap:  5242872k total,      484k used,  5242388k free,  2924724k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                             
27984 postgres  15   0 1125m  70m  68m S  6.3  1.8   0:00.19 postgres: postgres geo 10.11.4.34(46062) idle in transaction                                                         
27983 postgres  15   0 1125m  76m  74m S  5.6  1.9   0:00.39 postgres: postgres geo 10.11.4.34(43810) idle                                                                         
15647 postgres  18   0 1130m 1.0g 1.0g D  1.3 26.6   1:12.55 postgres: pointage geo 192.168.2.25(2721) SELECT                                                                     
15772 postgres  18   0 1130m 1.0g 1.0g D  1.3 26.6   0:59.29 postgres: pointage geo 192.168.2.14(4063) SELECT                                                                     
4753 postgres  15   0 1130m 1.0g 1.0g D  0.7 26.6   2:01.74 postgres: pointage geo 192.168.2.14(1685) SELECT                                                                     
4242 postgres  15   0 1130m 1.0g 1.0g D  0.3 26.7   2:01.03 postgres: pointage geo 192.168.2.37(1336) SELECT                                                                     
27982 postgres  15   0 12872 1220  828 R  0.3  0.0   0:00.06 top                                                                                                                   
1756 postgres  15   0 1133m 181m 174m S  0.0  4.6   0:07.41 postgres: pointage geo 192.168.2.17(1761) idle                                                                       
3142 postgres  15   0 91040 1772 1004 S  0.0  0.0   0:00.06 sshd: postgres@pts/3                                                                                                 
3143 postgres  15   0 66212 1636 1212 S  0.0  0.0   0:00.05 -bash                                                                                                                 
3507 postgres  15   0 1123m  25m  25m S  0.0  0.7   0:15.26 /usr/local/pgsql/bin/postmaster -D /home/postgres/PG_DATA                                                             
3510 postgres  15   0 72828  820  392 S  0.0  0.0   0:45.65 postgres: logger process                                                                                             
4123 postgres  15   0 1126m 476m 473m S  0.0 12.0   0:02.66 postgres: basicgeo geo 192.168.2.14(1660) idle                                                                       
4894 postgres  18   0 1660m 501m 8100 S  0.0 12.7   2:03.58 /usr/java/jre1.6.0_12/bin/java -cp /home/ServeurGEO/JAR/ServeurGEO.jar ServeurGEO /home/ServeurGEO/CONFIG/Config_Serve
5177 postgres  15   0 1135m 291m 282m S  0.0  7.4   0:13.66 postgres: pointage geo 127.0.0.1(45562) idle                                                                         
5952 postgres  15   0 90116 1736 1000 S  0.0  0.0   0:00.00 sshd: postgres@pts/4                                                                                                 
5953 postgres  15   0 66208 1644 1212 S  0.0  0.0   0:00.02 -bash                                                                                                                 
6375 postgres  15   0 1137m 291m 279m S  0.0  7.4   0:21.01 postgres: pointage geo 127.0.0.1(42617) idle                                                                         
8031 postgres  15   0 90116 1760 1004 S  0.0  0.0   0:00.01 sshd: postgres@pts/5                                                                                                 
8038 postgres  15   0 66212 1668 1212 S  0.0  0.0   0:00.02 -bash                                                                                                                 
8360 postgres  15   0 1130m  20m  15m S  0.0  0.5   0:00.24 postgres: postgres geo 192.168.71.45(49465) idle                                                                     
9300 postgres  15   0 1125m 104m 102m S  0.0  2.6   0:03.74 postgres: serveurgeo geo 127.0.0.1(42412) idle                                                                       
9478 postgres  18   0 1300m  49m 8012 S  0.0  1.2   0:03.70 /usr/java/jre1.6.0_12/bin/java -cp /home/ServeurOF/JAR/Serveur_OF.jar Serveur_OF /home/ServeurOF/CONFIG/Config_Serveur
11795 postgres  15   0 1134m  98m  89m S  0.0  2.5   0:04.02 postgres: pointage geo 127.0.0.1(45288) idle                                                                         
11806 postgres  15   0 1135m  91m  82m S  0.0  2.3   0:03.66 postgres: pointage geo 127.0.0.1(45289) idle                                                                         
13133 postgres  15   0 1135m 204m 195m S  0.0  5.2   0:04.48 postgres: pointage geo 127.0.0.1(45310) idle                                                                         
13536 postgres  15   0 1138m  93m  83m S  0.0  2.4   0:02.53 postgres: pointage geo 127.0.0.1(45315) idle                                                                         
18462 postgres  15   0 1126m  24m  21m S  0.0  0.6   0:01.73 postgres: cumul geo 192.168.2.25(2845) idle                                                                           
19651 postgres  15   0 1124m 754m 753m S  0.0 19.1   0:01.03 postgres: writer process                                                                                             
19652 postgres  15   0 1124m 2084 1620 S  0.0  0.1   0:00.19 postgres: wal writer process                                                                                         
19653 postgres  15   0 1124m 1188  596 S  0.0  0.0   0:00.00 postgres: autovacuum launcher process                                                                                 
19654 postgres  15   0 72960  948  400 S  0.0  0.0   0:03.46 postgres: stats collector process                                                                                     
20033 postgres  15   0 1130m 195m 190m S  0.0  5.0   0:01.05 postgres: pointage geo 127.0.0.1(39622) idle                                                                         
20691 postgres  15   0 1141m 1.0g 1.0g S  0.0 26.9   1:03.96 postgres: pointage geo 127.0.0.1(50710) idle                                                                         
21825 postgres  15   0 1138m 400m 388m S  0.0 10.1   0:10.42 postgres: pointage geo 127.0.0.1(34536) idle                                                                         
22233 postgres  15   0 1134m  93m  85m S  0.0  2.4   0:00.89 postgres: pointage geo 127.0.0.1(35337) idle                                                                         
23581 postgres  15   0 1127m  32m  29m S  0.0  0.8   0:00.60 postgres: cumul geo 192.168.2.17(2132) idle                                                                           
24173 postgres  15   0 1125m 4980 3476 S  0.0  0.1   0:00.00 postgres: postgres geo 192.168.71.45(50222) idle                                                                     
27437 postgres  15   0 1133m  98m  91m S  0.0  2.5   0:05.89 postgres: pointage geo 192.168.2.37(3298) idle                                                                       

La configuration PostgreSQL :
max_connections = 100
shared_buffers = 1024MB
work_mem = 10MB
maintenance_work_mem = 512MB
wal_buffers = 1MB
checkpoint_segments = 10
checkpoint_completion_target = 0.9
random_page_cost = 2.0
effective_cache_size = 2730MB
logging_collector = on
log_directory = '/home/postgres/PG_LOG'
log_filename = '%d.log'
log_truncate_on_rotation = on
log_min_duration_statement = 300
log_line_prefix = '%h %p %t %i %l '
log_statement = 'all'
log_autovacuum_min_duration = 300
autovacuum_naptime = 10min

J'ai demandé aujourd'hui, à l'équipe système d'installer des outils de diagnostic système (iotop, iostat, vmstat peut être). Ils vont voir.

J'espère que je ne suis pas trop gênant, en faisant de long post, mais j'essaye de fournir un maximum d'informations qui pourrait aider au diagnostic.

Hors ligne

#8 25/01/2013 00:03:18

gleu
Administrateur

Re : Que fait la requête ?

Les longs posts ne sont pas un problème. Le vrai soucis, c'est qu'il n'y a rien là-dedans qui puisse faire évoluer la réflexion sur votre soucis de performances. Tout ce qu'on voit, c'est qu'il y a quatre processus PostgreSQL qui sont plutôt bien sollicités. Les statistiques d'activité ne montrent rien de bien intéressants, surtout que ce ne sont les valeurs qu'à un point dans le temps.

Mon avis reste le même : tracez toutes les requêtes dans un fichier et faites analyser ce fichier par pgbadger.


Guillaume.

Hors ligne

#9 25/01/2013 11:31:34

mortimer.pw
Membre

Re : Que fait la requête ?

Bonjour,

Alors désolé pour tout le blabla inutile.

J'ai téléchargé, installé et regardé pgbadger sur un serveur de test, aucun probème tout semble ok.

Par contre pour l'installer sur le serveur en question, comme il faut faire de la modification de paramètres postgresql, il faut prévoir un arrêt/redémarrage et pas évident sur un serveur sollicité 24/24.
J'essaye de faire cela et de revenir vers vous au plus vite.

Cet outil à l'air bien sympa.

Merci encore pour vos réponses.

Dernière modification par mortimer.pw (25/01/2013 11:32:55)

Hors ligne

#10 25/01/2013 13:45:23

rjuju
Administrateur

Re : Que fait la requête ?

Quels paramètres devez-vous modifier ? Si logging_collector est déjà à on (sur votre précédent message), la modification du log_line_prefix ou de log_min_duration_statement ne nécessitent qu'un reload.

Hors ligne

#11 12/02/2013 15:19:59

mortimer.pw
Membre

Re : Que fait la requête ?

Bonjour,
Dimanche dernier, nous avons enfin mis en place la configuration nécessaire à l'exploitation des logs par PgBadger.
J'ai récupéré les logs de la journée d'hier, puis fait tourné PgBadger sur ces fichiers.
Nous avons maintenant plus d'informations sur l'activité de la base de données.

Le problème de requêtes longue est toujours présent sur la table citée plus haut dans le poste.

5h34m2.74s | UPDATE geo.ptg_pers SET id_type_ptg_sst = 'G' WHERE jour >= to_date ('20120901','YYYYMMDD')AND jour < to_date ('20121001','YYYYMMDD')AND id_type_ptg_sst = 'S';
1h57m47.04s | UPDATE geo.ptg_pers SET id_type_ptg_sst = 'G' WHERE jour >= to_date ('20120801','YYYYMMDD')AND jour < to_date ('20120901','YYYYMMDD')AND id_type_ptg_sst = 'S';

Est-il possible de poster le fichier de sortie de PgBadger sur le forum ? et comment ?

Merci pour les réponses.

Hors ligne

#12 12/02/2013 15:37:45

rjuju
Administrateur

Re : Que fait la requête ?

Il n'est pas possible d'envoyer des fichiers joints sur le forum. Vous pouvez toujours envoyer le fichier sur un site tiers et poster le lien ici.


Avez-vous activé la trace des  verrous ? (log_lock_waits = on). Cela ressemble plutôt à une requête bloquée, et pgBadger pourra vous afficher les informations. Vous devriez avoir l'heure d'exécution de ces requêtes, vous pouvez mettre ça en rapport avec diverses tâches de maintenance. Vous pouvez aussi activer les stats des procédures stockées (track_functions = pl), et regarder dans la vue pg_stat_user_functions si c'est la fonction j_geo.jf_ptg_pers qui prend beaucoup de temps.

Hors ligne

#13 12/02/2013 21:20:47

gleu
Administrateur

Re : Que fait la requête ?

Un EXPLAIN des deux requêtes serait intéressant (attention, pas un EXPLAIN ANALYZE car ça exécuterait réellement l'UPDATE smile ).


Guillaume.

Hors ligne

#14 15/02/2013 09:01:54

mortimer.pw
Membre

Re : Que fait la requête ?

Bonjour Messieurs,

Il ne m'est pas permis de diffuser le résultat du pgbadger à l'extérieur de l'entreprise.

Julien, oui les traces sur les verrous sont activés (mais pas de waiting à true dans pg_stat_activity et pas de granted à false dans pg_locks) et oui les stats sur les procédures stockées sont activés.

Guillaume, ci-dessous les résultats de l'explain :

geo=# EXPLAIN UPDATE geo.ptg_pers SET id_type_ptg_sst='G' WHERE jour>=to_date('20120901','YYYYMMDD') AND jour<to_date('20121001','YYYYMMDD') AND id_type_ptg_sst='S';
                                                                                   QUERY PLAN                                                                                   
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on ptg_pers  (cost=31383.82..179763.81 rows=100998 width=172)
   Recheck Cond: ((jour >= to_date('20120901'::text, 'YYYYMMDD'::text)) AND (jour < to_date('20121001'::text, 'YYYYMMDD'::text)) AND ((id_type_ptg_sst)::text = 'S'::text))
   ->  Bitmap Index Scan on ptg_pers_jour_type_ptg_sst_type_trt_ptg  (cost=0.00..31358.57 rows=100998 width=0)
         Index Cond: ((jour >= to_date('20120901'::text, 'YYYYMMDD'::text)) AND (jour < to_date('20121001'::text, 'YYYYMMDD'::text)) AND ((id_type_ptg_sst)::text = 'S'::text))

geo=# EXPLAIN UPDATE geo.ptg_pers SET id_type_ptg_sst='G' WHERE jour>=to_date('20120801','YYYYMMDD') AND jour<to_date('20120901','YYYYMMDD') AND id_type_ptg_sst='S';
                                                                                   QUERY PLAN                                                                                   
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on ptg_pers  (cost=21622.37..130944.50 rows=69581 width=172)
   Recheck Cond: ((jour >= to_date('20120801'::text, 'YYYYMMDD'::text)) AND (jour < to_date('20120901'::text, 'YYYYMMDD'::text)) AND ((id_type_ptg_sst)::text = 'S'::text))
   ->  Bitmap Index Scan on ptg_pers_jour_type_ptg_sst_type_trt_ptg  (cost=0.00..21604.97 rows=69581 width=0)
         Index Cond: ((jour >= to_date('20120801'::text, 'YYYYMMDD'::text)) AND (jour < to_date('20120901'::text, 'YYYYMMDD'::text)) AND ((id_type_ptg_sst)::text = 'S'::text))

Merci pour votre aide.

Hors ligne

#15 17/02/2013 20:31:01

gleu
Administrateur

Re : Que fait la requête ?

Si je puis me permettre, ce ne sont pas les plans d'exécution des UPDATE. Il y aurait une opération Update tout au début comme ici :

postgres=# explain update toto set id=10;
                          QUERY PLAN                          
--------------------------------------------------------------
 Update on toto  (cost=0.00..34.00 rows=2400 width=6)
   ->  Seq Scan on toto  (cost=0.00..34.00 rows=2400 width=6)
(2 rows)

Néanmoins, ce qu'on voit sur ces deux requêtes (qui visent le mois de septembre pour la première et le mois d'août pour la seconde), c'est qu'elles sont identiques dans leur plan d'exécution. Elles utilisent un index (ptg_pers_jour_type_ptg_sst_type_trt_ptg). La première récupère 100998 lignes et la seconde 69581. La première sera donc plus lente que la seconde. D'ailleurs le coût indiqué est plus important pour la première, dans la même proportion que celle du nombre de lignes.

Bref, on n'en tire pas grand chose pour l'instant.

Pouvez-vous faire un EXPLAIN (ANALYZE,BUFFERS) de l'UPDATE dans une transaction que vous annulerez pour en savoir un peu plus ?


Guillaume.

Hors ligne

#16 21/02/2013 08:40:39

mortimer.pw
Membre

Re : Que fait la requête ?

Bonjour Guillaume,

Je suis sur une version 8.4.2 et je crois que je ne peux pas faire de explain (analyze,buffers).

Hors ligne

#17 21/02/2013 17:59:24

gleu
Administrateur

Re : Que fait la requête ?

Vous avez raison, cette syntaxe date de la 9.0. Par contre, vous pouvez faire un "EXPLAIN ANALYZE".


Guillaume.

Hors ligne

Pied de page des forums