Que fait la requête ?

mortimer.pw · 23/01/2013 15:18:22

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)

gleu · 23/01/2013 15:42:16

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.

mortimer.pw · 24/01/2013 09:18:51

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)

rjuju · 24/01/2013 10:47:19

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.

mortimer.pw · 24/01/2013 12:08:19

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.

gleu · 24/01/2013 12:17:10

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.

mortimer.pw · 24/01/2013 12:53:15

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.

gleu · 25/01/2013 00:03:18

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.

mortimer.pw · 25/01/2013 11:31:34

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)

rjuju · 25/01/2013 13:45:23

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.

mortimer.pw · 12/02/2013 15:19:59

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.

rjuju · 12/02/2013 15:37:45

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.

gleu · 12/02/2013 21:20:47

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

mortimer.pw · 15/02/2013 09:01:54

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.

gleu · 17/02/2013 20:31:01

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 ?

mortimer.pw · 21/02/2013 08:40:39

Bonjour Guillaume,

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

gleu · 21/02/2013 17:59:24

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

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

Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

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

Re : Que fait la requête ?

Pied de page des forums

PostgreSQL.fr

À propos

Nous contacter

Groupes Locaux

Réseaux Sociaux