Postgresql applicatie: db optimalisatie

[Boudewijn]

Hoihoi


Ik ben voor een klant bezig met een applicatie die data over glasvezels bijhoudt. Dit gebeurt in 2 delen, een deel met geografische data (WKT formaat) en een deel met overige informatie (eigenaar, lengte, SLA etc).
Dat laatste deel is voor dit topic niet boeiend, dat loopt prima en levert geen relevante load op.

De actionscript interface (hij is niet door mij gemaakt, maar ik ben er nu wel verantwoordelijk voor) heeft als doel de locaties van die glasvezels op een google-maps achtig ding (de kaart komt van MS) te plotten.
Prima, maar dit levert een forse (!) load op op de virtuele machine waar dit geheel op draait. Een standaard kaartview van een gemiddelde stad kan gewoon 3-4-5 minuten staan te laden. Postgres biedt deze data aan door middel van de postgis uitbreiding, wat een geografisch informatie systeem mogelijk maakt in postgres.

Ik weet niet wat er exact in die applet gebeurt, maar mijn collega (die het ding heeft gemaakt) heeft hem naar eigen zeggen redelijk geoptimaliseerd. Ik heb geen reden om hieraan te twijfelen, hij komt kundig over .

Echter is de database hier nooit op berekend geweest en is er een gebrek aan indices, en andere optimalisaties. Ik wil niet overhaast gaan beginnen met indices aanmaken, want "eerst denken en dan doen" is een goed devies .

Het lijkt me allereerst nuttig om uit te zoeken welke queries nou zo traag zijn (of van welke queries er heel veel zijn....). Ik zie dat ik queries kan loggen in postgresql, en daarvoor heb ik de volgende settings aangemaakt:

code:

log_duration = on
log_line_prefix = '%t '# special values:
log_statement = 'all'# none, ddl, mod, all
track_activities = on
track_counts = on
update_process_title = on
log_statement_stats = on

Hiermee kan ik log bij elkaar krijgen van welke queries ik uitvoer als ik een kaartje bekijk:
Het gaat trouwens om pgsql-8.3.


Ik ga zo eens een sessie uitvoeren waarbij ik een kaartje opvraag en dan die queries bekijken, maar hij staat nu al 2 minuten te stampen met *veel* queries die ik in de log voorbij zie komen.


Waar kan ik het beste op letten, of zijn hier best practices voor? Tevens hebbe we het hier bijna voor 100% over read-only operaties. Deadlock door rare transacties of rollbacks is niet van toepassing.
De view-mode geeft al genoeg vertraging; tegen de tijd dat die goed werkt gaan we eens kijken of de write-mode ook aan te pakken is.

Een andere database-engine is een no-go, domweg omdat we redelijk aan postgis vastzitten.

[ Voor 9% gewijzigd door Boudewijn op 01-01-2010 17:04 ]

[doskabouter]

Als eerste zou ik in ieder geval een index op de geo leggen. Als die er nog niet was gaat dat heel veel schelen

[Boudewijn]

Dat klopt, maar ik momenteel nog niet op welke geodata het probleem zit. Dat wil ik eigenlijk eerst uitzoeken.
Zo maar willekeurig indices aanmaken lijkt me ook niet handig, volgens mij was dat zelfs contra-productief.


Ik heb nu een logje liggen van mijn applicatie en dat logje is 38k regels logfile voor het eenmaal (!) bekijken van de kaart. En ik ben de enige die gebruik maakt van die testmachine... dus het is allemaal van mij .

De vorm is als volgt:

code:

2010-01-01 17:05:15 CET LOG:  statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
2010-01-01 17:05:15 CET LOG:  duration: 0.062 ms
2010-01-01 17:05:15 CET LOG:  QUERY STATISTICS
2010-01-01 17:05:15 CET DETAIL:  ! system usage stats:
    !   0.000069 elapsed 0.000000 user 0.000000 system sec
    !   [0.184011 user 0.068004 sys total]
    !   0/0 [0/0] filesystem blocks in/out
    !   0/0 [0/1979] page faults/reclaims, 0 [0] swaps
    !   0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
    !   0/0 [1118/45] voluntary/involuntary context switches
    ! buffer usage stats:
    !   Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
    !   Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
    !   Direct blocks:          0 read,          0 written
2010-01-01 17:05:15 CET STATEMENT:  BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
2010-01-01 17:05:15 CET LOG:  statement: SELECT "Login".id AS "Login_id", "Login".user^C

En dit per query....
Als ik ga greppen op select queries valt dat enorm mee ,maar 800 queries.


Goed, ik kan hier nog mee doorgaan maar is dit niet een beetje slim te automagiseren? Ik zou een profiler erg handig vinden, maar vind alleen pgtop... en die is vrij rudimentair voor mijn doeleinden.

Wat wel opvalt is dat er HEEL veel authenticatie-queries voorbij komen, daar ga ik ook eens naar kijken. En wat nog meer opvalt: hij loopt continu rollbacks van transacties uit te voeren.. maar ik lees alleen:

code:

2010-01-01 17:05:16 CET STATEMENT:  SELECT "User"."Username" AS "User_Username", "User"."Fullname" AS "User_Fullname", "User"."Email" AS "User_Email", "User"."AdminRight" AS "User_AdminRight", "User"."GeoRight" AS "User_GeoRight", "User"."SoapRight" AS "User_SoapRight", "User"."WebRight" AS "User_WebRight", "User".last_updated AS "User_last_updated", "User".last_updated_by AS "User_last_updated_by"
        FROM "User"
2010-01-01 17:05:16 CET LOG:  statement: ROLLBACK
2010-01-01 17:05:16 CET LOG:  duration: 0.044 ms
2010-01-01 17:05:16 CET LOG:  QUERY STATISTICS
2010-01-01 17:05:16 CET DETAIL:  ! system usage stats:
        !       0.000053 elapsed 0.000000 user 0.000000 system sec
        !       [0.260016 user 0.100006 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/2076] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [1570/116] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
2010-01-01 17:05:16 CET STATEMENT:  ROLLBACK
2010-01-01 17:05:16 CET LOG:  statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
2010-01-01 17:05:16 CET LOG:  duration: 0.055 ms
2010-01-01 17:05:16 CET LOG:  QUERY STATISTICS
2010-01-01 17:05:16 CET DETAIL:  ! system usage stats:
        !       0.000064 elapsed 0.000000 user 0.000000 system sec
        !       [0.208013 user 0.068004 sys total]
        !       0/0 [0/0] filesystem blocks in/out
        !       0/0 [0/2004] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       0/0 [1235/45] voluntary/involuntary context switches
        ! buffer usage stats:
        !       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
        !       Direct blocks:          0 read,          0 written
2010-01-01 17:05:16 CET STATEMENT:  BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
2010-01-01 17:05:16 CET LOG:  statement: SELECT "User"."Username" AS "User_Username", "User"."Fullname" AS "User_Fullname", "User"."Email" AS "User_Email", "User"."AdminRight" AS "User_AdminRight", "User"."GeoRight" AS "User_GeoRight", "User"."SoapRight" AS "User_SoapRight", "User"."WebRight" AS "User_WebRight", "User".last_updated AS "User_last_updated", "User".last_updated_by AS "User_last_updated_by"
        FROM "User"
2010-01-01 17:05:16 CET LOG:  duration: 0.163 ms
2010-01-01 17:05:16 CET LOG:  QUERY STATISTICS
2010-01-01 17:05:16 CET DETAIL:  ! system usage stats:

Kan iemand me een hint geven in welke richting ik moet zoeken op het gebied van die rollbacks?

Edit:
Ik loop nu net tegen 'pqa' aan, een query analyse scriptje, zal dat eens gaan bekijken.

[TGEN]

Draai je al met enige regelmaat ANALYZE op je tables? Als je de autovacuum functie gebruikt wordt dat al automatisch gedaan, maar alleen na een X aantal inserts/updates/deletes. Ook kan je een 'willekeurig' indices aanmaken die je vervolgens vanuit cron oid met enige regelmaat aanpast met REINDEX.

[Boudewijn]

Dat is op zich ook wel een goede. Ik zou eventueel de cache van de DB eens wat op kunnen voeren.

Echter zit ik me af te vragen hoe ik nou het beste objectief de verbeteringen a meten.
Mijn idee is om een sessie of 5 te loggen qua queries en die set queries vervolgens af te vuren op de DB.


Echter zit je daar dus met het feit dat je je buffer in feite loopt te benchmarken.

Kan ik dat slim doen? Want anders weet ik niet wat mijn tweaks opleveren.... sowieso is het gewoon leuk om te zien wat aanpassingen voor gevolg hebben.

[ Voor 7% gewijzigd door Boudewijn op 02-01-2010 00:21 ]

[DamadmOO]

Boudewijn schreef op vrijdag 01 januari 2010 @ 17:23:
En dit per query....
Als ik ga greppen op select queries valt dat enorm mee ,maar 800 queries.

800 queries voor het laden van 1 ding voor 1 persoon klinkt mij als VEEL te veel in de oren. Ik weet dan niet precies wat de applicatie doet/laat zien. Maar het klinkt mij alsof er initieel iets geselecteerd wordt en aan de hand daarvan een loop begint. Dat kan in veel gevallen geoptimaliseerd worden.

Boudewijn schreef op vrijdag 01 januari 2010 @ 17:23:
Kan iemand me een hint geven in welke richting ik moet zoeken op het gebied van die rollbacks?

Wordt er een update naar de user tabel gedaan? Zo ja dan is dat de reden. Je kan hier omheen door een ander isolation level te gebruiken. Maar ik vind de query zelf nogal raar aangezien er geen enkele where clausule gebruikt wordt. Dat kan gebruikt worden om een array te vullen op het begin. Maar doordat jij zelf zegt dat de query vaak voorbij komt heb ik daar toch mijn vraagtekens bij.

[Boudewijn]

Neen die user tabel is hardstikke statisch (usertje of 25-30):

code:

Username   |       Fullname        |              Email              | AdminRight | GeoRight | SoapRight | WebRight |         last_updated          | last_updated_by
surfnet bv_ector   | *mijn naam*       | *email*     | 1          | 0        | 0         | 0        | 2010-01-01 15:13:51.929377+01 |

Die last_updated is het waarop de rechten van de user aangepast worden.
Verder ben ik de enige user die inlogt op die testmachine (ik heb wel een goede copie van de database).


800 queries: jep, mij ook. Het probleem is dat er een stateless applet is (vziw) die via SOAP communiceert met de python applicatie (die ook ORM is). Daar is dus een forse lading authenticaties voor nodig.

Echter, draait er ook een webinterface die ook regelmatig authenticeert (voor veel functionaliteiten worden de rechten van de user voor een functieaanroep gecheckt).


Over het querien voor de kaartdata zelf:

Er worden veel coordinaten opgevraagd van zo'n glasvezel. Hierna worden hier coordinaten uitgeilterd zodat een wat kleinere set naar de applet gaat (afhankelijk van je zoomniveau) en vervolgens wordt geplot.


Waarom mijn relatieve ontwetendheid: ik ben de ontwikkelaar van de python code en ik gebruik de ORM. Mijn collega (die volgende week weggaat ) heeft die applet gemaakt. Ik kan hem deze week nog goed spammen, en daarna wordt het lastig.

Uiteraard was documenteren geen prioriteit (mijnerzijds wel, maar dat gold niet voor iedereen).

[ACM]

Boudewijn schreef op vrijdag 01 januari 2010 @ 17:02:
log_statement_stats = on

Ik zou die in eerste instantie maar even uit laten... Dan krijg je niet al die extra statistieken erbij, waar je in eerste instantie toch niet zoveel hebt.

2010-01-01 17:05:15 CET LOG: statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED

Die, gecombineerd met de rollback die later terugkomt suggereert dat er voor elke query - overbodig - een losse transactie wordt gestart. Dat zal wel de bijwerking van eoa waardeloos communicatie-geheel zijn. 't Zou me niks verbazen als je ORM dat gewoon standaard voor elke query toevoegt, en als ie geen commit meekrijgt maar gewoon een rollback toevoegt.
Ook kan het zijn dat je voor elke query een nieuwe connectie maakt en in dat geval heb je iig al een vertragingspunt gevonden. Beide gedragingen zijn nogal overbodig, maar zal ook weer niet het allergrootste deel van de tijd innemen.

Als ik ga greppen op select queries valt dat enorm mee ,maar 800 queries.

800 queries is best veel, dus ik zou als ik jou was es kijken welke het zijn en hoelang ze duren. Je kan eventueel ook nog een log_min_duration (oid) toevoegen in je configuratie, zodat je kan opgeven hoe lang een query moet duren voor ie in de log verschijnt. Die zou je dan op bijvoorbeeld een hoeveelheid tijd kunnen zetten die iig al die begin's en rollback's uitsluit.

Goed, ik kan hier nog mee doorgaan maar is dit niet een beetje slim te automagiseren? Ik zou een profiler erg handig vinden, maar vind alleen pgtop... en die is vrij rudimentair voor mijn doeleinden.

Je kan kijken of er een log-analyzer is voor PostgreSQL. Maar gewoon goed filteren en eerst de traagste queries bekijken (en daar met EXPLAIN ANALYZE naar kijken) moet je al een heel eind helpen.

Wat wel opvalt is dat er HEEL veel authenticatie-queries voorbij komen, daar ga ik ook eens naar kijken. En wat nog meer opvalt: hij loopt continu rollbacks van transacties uit te voeren.. maar ik lees alleen:

Dat onderschrijft mijn suggestie dat er voor elke query een losse connectie wordt gemaakt...

[Boudewijn]

In hoeverre heeft het zin om nu een logfile aan te maken van de gerunde queries en die na het maken van een verbetering opnieuw de DB in te sturen?

Dit wil ik doen om de performance-verbeteringen te vergelijken, maar ik ben bang dat ik alleen de performance van mijn buffers onderzoek .

[ Voor 4% gewijzigd door Boudewijn op 03-01-2010 17:26 ]

[ACM]

Boudewijn schreef op zondag 03 januari 2010 @ 17:23:
Dit wil ik doen om de performance-verbeteringen te vergelijken, maar ik ben bang dat ik alleen de performance van mijn buffers onderzoek .

Als je er goed voor oppast dat je buffers goed gevuld zijn en dus de query-tijden behoorlijk stabiel, dan zou e.e.a. een redelijk beeld van de winsten moeten geven.

[JaQ]

ACM schreef op zaterdag 02 januari 2010 @ 11:28:
Die, gecombineerd met de rollback die later terugkomt suggereert dat er voor elke query - overbodig - een losse transactie wordt gestart. Dat zal wel de bijwerking van eoa waardeloos communicatie-geheel zijn. 't Zou me niks verbazen als je ORM dat gewoon standaard voor elke query toevoegt, en als ie geen commit meekrijgt maar gewoon een rollback toevoegt.

Gelukkig hebben de meeste ORM's hier een setting voor (iets met persistency)

[Boudewijn]

ACM schreef op zondag 03 januari 2010 @ 17:48:
[...]

Als je er goed voor oppast dat je buffers goed gevuld zijn en dus de query-tijden behoorlijk stabiel, dan zou e.e.a. een redelijk beeld van de winsten moeten geven.

Klopt, dus ik zou eigenlijk mijn set queries 5x moeten draaien oid en de laatste 3 keer moeten timen en die tijden dan middelen oid?

[cariolive23]

de virtuele machine

Dit is 9 van de 10 keer al een probleem, tenzij er speciale configuraties zijn opgesteld zodat de database zelfs op een vm redelijke tot goede prestaties neer kan zetten. Hebben jullie dat gedaan?

En staan er nog andere vm's op de server waar jouw vm op draait? Deze vm's kunnen jou flink in de weg zitten, zeker wat betreft de schijven. Je hebt maar één portie I/O tot je beschikking, deze moet je met alle vm's delen. En omdat I/O voor iedere database al een knelpunt is, wordt dat met vm's een nog veel groter knelpunt.

En de configuratie in zijn algemeenheid, is daar de nodige aandacht aan besteed? Kun je postgresql.conf hier eens plaatsen, kunnen we even meekijken.

ORM maakt de problemen nog groter, je hebt dan geen enkele controle meer over de queries. 800 queries per actie, dat is niet handig, kan eigenlijk nooit snel zijn.

Wanneer je de logs laat aanmaken in csv-formaat, kun je deze met COPY importeren in je database en de queries automatisch laten EXPLAIN-en. Deze resultaten kun je dan weer min of meer automatisch laten verwerken.

Maar voordat je gaat explainen, zorg eerst voor een goede basis configuratie van je database. Zonder deze basis heeft het geen zin om te gaan explainen, je weet dan vooraf al dat de boel langzaam blijft en dat de resultaten van explain "verkeerd" zijn.

Zorg er ook voor dat je tijdens het explainen de database even dwingt om de beschikbare indexen te gebruiken:
SET enable_seqscan TO off;

[Boudewijn]

Goed, dit is mijn huidige config:

code:

boudewijn@test:~$ grep -v "^#" /etc/postgresql/8.3/main/postgresql.conf  | sed   "s/\t//g" | grep -v "^#" | grep -v "^$"
data_directory = '/var/lib/postgresql/8.3/main'# use data in another directory
hba_file = '/etc/postgresql/8.3/main/pg_hba.conf'# host-based authentication file
ident_file = '/etc/postgresql/8.3/main/pg_ident.conf'# ident configuration file
external_pid_file = '/var/run/postgresql/8.3-main.pid'# write an extra PID file
listen_addresses = '127.0.0.1'# what IP address(es) to listen on;
port = 5432# (change requires restart)
max_connections = 100# (change requires restart)
unix_socket_directory = '/var/run/postgresql'# (change requires restart)
ssl = true# (change requires restart)
shared_buffers = 24MB# min 128kB or max_connections*16kB
max_fsm_pages = 153600# min max_fsm_relations*16, 6 bytes each
log_destination = 'stderr'# Valid values are combinations of
logging_collector = on# Enable capturing of stderr and csvlog
log_directory = '/var/log/pg_log'# directory where log files are written,
log_filename = 'postgresql-%Y-%m-%d.log'# log file name pattern,
log_rotation_size = 1024MB# Automatic rotation of logfiles will
client_min_messages = notice# values in order of decreasing detail:
log_min_messages = notice# values in order of decreasing detail:
log_error_verbosity = default# terse, default, or verbose messages
log_min_error_statement = error# values in order of decreasing detail:
 #   debug5
 #   info
log_duration = on
log_line_prefix = ''  #'%t '# special values:
log_statement = 'all'# none, ddl, mod, all
track_activities = off
track_counts = on
update_process_title = off
log_parser_stats = off
log_planner_stats = off
log_executor_stats = off
log_statement_stats = off
autovacuum = on# Enable autovacuum subprocess?  'on'
log_autovacuum_min_duration = -1# -1 disables, 0 logs all actions and
datestyle = 'iso, mdy'
lc_messages = 'en_US.UTF-8'# locale for system error message
lc_monetary = 'en_US.UTF-8'# locale for monetary formatting
lc_numeric = 'en_US.UTF-8'# locale for number formatting
lc_time = 'en_US.UTF-8'# locale for time formatting
default_text_search_config = 'pg_catalog.english'

Bij de opdrachtgever is er geen ruimte voor een eigen machine... ik kan wel een db krijgen op een algemene server, maar die ondersteunt weer geen postgis. Dat werkt dus niet, ik moet roeien met de riemen die ik heb. Qua VM is er ook weinig te regelen, men is daar nogal stug in.


Dit is een tamelijk standaard pgsql configfile, hier is zeker winst op te pakken.
Ik ga denk ik eerst eens kijken hoe dat copy+csv formaat werkt, dan kan ik in ieder geval met een standaardset queries de performance vergelijken .

[cariolive23]

shared_buffers = 24MB

Ik heb niet de indruk dat hier ooit iemand met kennis iets mee heeft gedaan, dit is zéér minimaal, hier kan een database nooit enige performance mee bereiken. In de Formule 1 rijden ze tenslotte ook niet op 1 cilindertje en slechts 3 wielen...

Ik verwacht dat de overige onderdelen (die je hier niet noemt) soortgelijke standaard instellingen bevatten en dus ook de boel zeer beperken. Ga dit eerst configureren, dan zal e.e.a. al een stuk sneller moeten gaan werken.

http://wiki.postgresql.org/wiki/Performance_Optimization

Een VM is een blok aan het been, maar daar kiest men zelf voor. Verwacht dus geen wonderen, dat is technnisch niet mogelijk.

[Boudewijn]

cariolive23 schreef op maandag 04 januari 2010 @ 19:55:
Ik heb niet de indruk dat hier ooit iemand met kennis iets mee heeft gedaan, dit is zéér minimaal, hier kan een database nooit enige performance mee bereiken. In de Formule 1 rijden ze tenslotte ook niet op 1 cilindertje en slechts 3 wielen...

Een afgestudeerd HBO informaticus heeft dit opgezet. Dit heeft op een algemene (extern beheerde) server gedraaid tot een jaar geleden en is toen in een out of the box debian VM neergezet.

Ik verwacht dat de overige onderdelen (die je hier niet noemt) soortgelijke standaard instellingen bevatten en dus ook de boel zeer beperken. Ga dit eerst configureren, dan zal e.e.a. al een stuk sneller moeten gaan werken.

Such as? De ORM? DB design?
Dat laatste zit redelijk snor, de ORM is wat inefficient lijkt het ( ) gezien de hoeveelheid rollbacks.

cariolive23 schreef op maandag 04 januari 2010 @ 19:55:
Een VM is een blok aan het been, maar daar kiest men zelf voor. Verwacht dus geen wonderen, dat is technnisch niet mogelijk.

Ik kies er niet voor, ik mag de shit opruimen. Ben software engineer, en ben hier ook niet voor ingehuurd... maar mag het wel doen.
Vind het ook wel leuk wat te leren.
Echter is je cache vergroten wel leuk ,maar helpt dat niet met het efficienter maken van queries. Cache is na een tijdje ook op.

[bloody]

ACM schreef op zaterdag 02 januari 2010 @ 11:28:

Je kan kijken of er een log-analyzer is voor PostgreSQL. Maar gewoon goed filteren en eerst de traagste queries bekijken (en daar met EXPLAIN ANALYZE naar kijken) moet je al een heel eind helpen.

Zie ook pgadmin, de standaard GUI voor postgresql. Daar zit een heel fijn (persoonlijk ) grafische weergave van die explain in. Zo kun je direct zien waar in de query-executie een volledige scan van een tabel plaatsvindt, en je dus een index zou kunnen plaatsen.

[cariolive23]

Boudewijn schreef op maandag 04 januari 2010 @ 20:09:
Een afgestudeerd HBO informaticus heeft dit opgezet. Dit heeft op een algemene (extern beheerde) server gedraaid tot een jaar geleden en is toen in een out of the box debian VM neergezet.

Prachtig, maar dat wil niet zeggen dat iemand de ins en outs van PostgreSQL kent. De configuratie die je hier voorschotelt, is niet meer dan de standaard configuratie, daar hoef je dus helemaal niets voor te doen, laat staan informatica voor te hebben gestudeerd. De verantwoordelijke specialist heeft hoogst waarschijnlijk niets aan de configuratie gedaan, anders hij/zij echt wel de shared_buffers aangepast of hier commentaar bij gezet: "onbruikbaar voor productie".

Such as? De ORM? DB design?
Dat laatste zit redelijk snor, de ORM is wat inefficient lijkt het ( ) gezien de hoeveelheid rollbacks.

Ik doel op postgresql.conf, de configuratie van de database. Wanneer je de database aan de ketting legt en laat hinken, kan deze nooit voor jou gaan rennen om snel een resultaat op te lepelen.

ORM is lastig maar dat kun je waarschijnlijk ook niet zo 1-2-3 veranderen.

Ik kies er niet voor, ik mag de shit opruimen. Ben software engineer, en ben hier ook niet voor ingehuurd... maar mag het wel doen.
Vind het ook wel leuk wat te leren.

Gelukkig!

Echter is je cache vergroten wel leuk ,maar helpt dat niet met het efficienter maken van queries. Cache is na een tijdje ook op.

Queries worden er niet efficienter van, je geeft de database wel de kans om zijn indexen in cache te zetten waardoor queries véél sneller kunnen worden uitgevoerd. Ook sorteeracties kunnen ineens in RAM worden gedaan, dat hoeft niet meer op schijf te gebeuren. Door het beschikbare RAM te gebruiken, wordt het gedrag van de database ineens totaal anders. Daarvoor hoef je geen enkele query aan te passen.

Het aanmaken van betere indexen wordt dan ook ineens zinvol, de indexen kunnen door de database worden gebruikt. Wanneer de database de boel eerst van schijf zou moeten halen, kan deze misschien net zo goed direct de data van schijf halen en de index links laten liggen. RAM is onmisbaar, maar dan moet je er wel gebruik van maken.

Zonder fatsoenlijke basisconfiguratie heeft het eigenlijk geen zin om te gaan optimaliseren. 24MB shared_buffers is gewoon achtelijk weinig.

[Boudewijn]

Wat is eigenlijk de lol van die logs in CSV formaat? Dat je met een sql statement het log in kunt laden en nogaals uitvoeren?

Volgens mij is het veel handiger als je alleen de statements logt en die vanuit bash (desnoods in een forloopgje als je meerdere runs wil) uit laat voeren.

Waar ergens zit mijn denkfout?
CSV is handig naar andere toepassingen toe, maar dat wil ik niet.

[cariolive23]

Hoe jij de logs uitleest en laat explainen, dat maakt toch niet uit? Er zijn meerdere wegen die naar Rome leiden. Eén daarvan is opslaan in csv-formaat en importeren/explainen in de database zelf een andere oplossing is een bash scriptje. Net wat jij leuk vindt, het gaat om het eindresultaat: Hoe wordt de query uitgevoerd en waarom wordt de query zo uitgevoerd?

Maar het heeft weinig zin om te gaan explainen met je huidige configuratie, ga die eerst maar eens flink verbeteren. De queryplanner kan weinig beginnen met een configuratie die slechts een heel klein beetje RAM-gebruik toestaat.

[Boudewijn]

Aub, lees aub de thread eens goed. Dat ik dat RAM moet toevoegen is al lang bekend.

Ik wil gewoon eerst een goed logje zonder overige info, met louter de statements.
Dit kan ik ter referentie blijven draaien, zodat ik een objectieve vergelijking kan maken. Dan kan ik laten zien hoeveel 'winst' ik maak met waarschuwingen.

Dat gaat niet handig met een CSV.

Als ik nu ga loggen vind ik dit :

code:

LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "Fiber_FiberID_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "GeoItem_GeoItemID_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "GeoObject_GeoObjectID_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "Line_Length_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "Login_id_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "SRLG_SRLGID_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "Section_Length_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "Section_SectionID_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from "SiteName_SiteNameID_seq"
LOG:  statement: SELECT sequence_name, last_value, increment_by, CASE WHEN increment_by > 0 AND max_value = 9223372036854775807 THEN NULL      WHEN increment_by < 0 AND max_value = -1 THEN NULL      ELSE max_value END AS max_value, CASE WHEN increment_by > 0 AND min_value = 1 THEN NULL      WHEN increment_by < 0 AND min_value = -9223372036854775807 THEN NULL      ELSE min_value END AS min_value, cache_value, is_cycled, is_called from changelog_change_id_seq

Met de volgende settings:

code:

log_destination = 'stderr'              # Valid values are combinations of
                                        # stderr, csvlog, syslog and eventlog,
                                        # depending on platform.  csvlog
                                        # requires logging_collector to be on.
logging_collector = on          # Enable capturing of stderr and csvlog
                                        # into log files. Required to be on for
                                        # csvlogs.
log_directory = '/var/log/pg_log'               # directory where log files are written,
log_filename = 'postgresql.log'
                                        # same name as the new log file will be
log_rotation_size = 1024MB              # Automatic rotation of logfiles will
                                        # happen after that much log output.
                                        #   log
log_min_messages = notice               # values in order of decreasing detail:
                                        #   log
log_error_verbosity = default           # terse, default, or verbose messages
log_min_error_statement = error # values in order of decreasing detail:
                                        #   log
                                        # and their durations, > 0 logs only
                                        # logging_collector
log_duration = off
log_line_prefix = ''  #'%t '                    # special values:
log_lock_waits = off                    # log lock waits >= deadlock_timeout
log_statement = 'all'                   # none, ddl, mod, all
                                        # -1 disables, 0 logs all temp files
log_parser_stats = off
log_planner_stats = off
log_executor_stats = off
log_statement_stats = off
log_autovacuum_min_duration = -1        # -1 disables, 0 logs all actions and
                                        # their durations, > 0 logs only

Volgens mij heb ik nu alles uitgezet qua extra info... en toch krijg ik geen queries uit dat log.


Edit:

Et voila:
test:/var/log/pg_log# grep statement postgresql.log.1262640132 | sed "s/LOG: statement: //g" | sed "s/$/;/g"
Ik ga sowieso een stevige log maken met 10-15 user interacties draaien... en die logs ga ik gebruiken zometeen. Dan kan ik mooi meten en vergelijkn.

[Boudewijn]

Hmm dat werkt dus ook niet, ik houd dan een aantal incomplete queries over, zoals:

code:

SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL);
SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL);
SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL);
SELECT pg_catalog.format_type('16'::pg_catalog.oid, NULL);

Weet nou niemand een optie om alleen queries (Zoals ze binnenkomen in de DB) te loggen?

[cariolive23]

Dit komt binnen op de database en dus wordt het gelogd. Het zijn complete queries, niets mis mee.

Wanneer jij alleen queries van jouw applicatie wilt laten loggen, zorg er dan voor dat je deze kunt herkennen door met een eigen database user te connecten en deze username ook in de logs te zetten.

Of ga loggen in je applicatie, maar dat kost extra werk.

[cariolive23]

Je kunt ook debug_print_plan aan zetten, dan wordt ieder queryplan direct in de loggings gezet.

log_min_duration_statement een hogere waarde geven, in millisecondes, kan er voor zorgen dat je alleen queries in je loggings krijgt die te lang duren.

Ps. debug_print_plan is wel echt debug informatie, in vergelijking met een normale explain krijg je wellicht een overdosis informatie. Met PostgreSQL versie 8.4 krijg je in de contrib een auto-explain meegeleverd, die levert voor jouw situatie betere en vooral duidelijker informatie op.

http://www.postgresql.org/docs/8.4/static/auto-explain.html

[ Voor 42% gewijzigd door cariolive23 op 05-01-2010 10:00 ]

[Boudewijn]

cariolive23 schreef op dinsdag 05 januari 2010 @ 07:17:
Dit komt binnen op de database en dus wordt het gelogd. Het zijn complete queries, niets mis mee.

Wanneer jij alleen queries van jouw applicatie wilt laten loggen, zorg er dan voor dat je deze kunt herkennen door met een eigen database user te connecten en deze username ook in de logs te zetten.

Dit is de *enige* applicatie op die installatie. Ze zijn dus gewoon van mijn applicatie.

cariolive23 schreef op dinsdag 05 januari 2010 @ 09:45:
Je kunt ook debug_print_plan aan zetten, dan wordt ieder queryplan direct in de loggings gezet.

log_min_duration_statement een hogere waarde geven, in millisecondes, kan er voor zorgen dat je alleen queries in je loggings krijgt die te lang duren.

Ps. debug_print_plan is wel echt debug informatie, in vergelijking met een normale explain krijg je wellicht een overdosis informatie. Met PostgreSQL versie 8.4 krijg je in de contrib een auto-explain meegeleverd, die levert voor jouw situatie betere en vooral duidelijker informatie op.

http://www.postgresql.org/docs/8.4/static/auto-explain.html

Dat weet ik... alleen ik wil momenteel alleen gewoon mijn queries teruglezen. Die wil ik opslaan en daarna nog een keer uit kunnen voeren. Dit om te beoordelen hoe efficient mijn verbeteringen zijn

[cariolive23]

Ik ben hem even kwijt, wat is nu nog het probleem? Je kunt blijkbaar logs aanmaken, dat is toch precies wat je nu wilt? Vervolgens kun je deze gebruiken om te explainen en te vergelijken met de resultaten na optimalisatie.

De opmerking over incomplete queries (die gewoon compleet zijn) waarvan je nu zelf zegt dat deze van jouw applicatie afkomstig zijn, kan ik niet plaatsen.

[Boudewijn]

Okay nog even opnieuw dan :

Ik vind dit soort dingen in mijn log:

code:

LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('25'::pg_catalog.oid, NULL)
LOG:  statement: SELECT pg_catalog.format_type('39620'::pg_catalog.oid, NULL)

Dit beschreef ik hier:
Boudewijn in "Postgresql applicatie: db optimalisatie"


Dat zijn gewoon halve queries.En zo zijn er meer (ik heb 150k regels log, dus ik ga ze hier niet allemaal copy-pasten).

[Mr_x007]

Dat zijn geen halve query's maar hij select iets uit een function

[cariolive23]

Boudewijn schreef op dinsdag 05 januari 2010 @ 11:03:
Dat zijn gewoon halve queries.

Probeer deze "halve queries" dan eens uit te voeren en je zult zien dat het gewoon complete queries zijn. Dat had ik je ook al gezegd.

Deze queries vragen de naam van een datatype op, het datatype dat hoort bij een bepaalt OID.