Warum dauert der erste SELECT mit der FTL um ein vielfaches länger?

Allgemeines zu PostgreSQL.

Warum dauert der erste SELECT mit der FTL um ein vielfaches länger?

Beitragvon pg_anfaenger » Di 3. Jul 2012, 10:39

Hallo zusammen,

ich habe eine Frage zu der Postgres Volltextsuche (inkl. Index):
In einer meiner Tabellen liegen ca. 1600000 Datensätze mit Produktinformationen (Produktbeschreibung, Preise,....).

Damit die Suche nach Produkten effektiv durchgeführt werden kann habe ich eine weitere Spalte in die Tabelle ergänzt und mit Suchdaten befüllt:


Code: Alles auswählen
alter table product add column searchindex tsvector;
update product set searchindex=to_tsvector('german', title || ' ' || desc_short || ' ' || desc_long);


Anschließend habe ich einen Index für die neue Spalte erzeugt:
Code: Alles auswählen
create index searchindex_idx on product using gist(searchindex);


Wenn ich jetzt eine Suche durchführe, dann dauert das erstmalige Suchen nach einem Suchbegriff um ein vielfaches länger als die darauffolgenden Suchen nach dem gleichen Suchbegriff
Code: Alles auswählen
select title from product where searchindex @@ to_tsquery('german', 'Badezusatz');



Ein EXPLAIN ANALYZE ergibt folgenden Output (Lauf 1)
Code: Alles auswählen
"Bitmap Heap Scan on product  (cost=74.84..3134.82 rows=814 width=37) (actual time=6602.427..7529.790 rows=197 loops=1)"
"  Recheck Cond: (searchindex @@ '''badezusatz'''::tsquery)"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..74.64 rows=814 width=0) (actual time=3058.503..3058.503 rows=1003 loops=1)"
"        Index Cond: (searchindex @@ '''badezusatz'''::tsquery)"
"Total runtime: 7530.378 ms"


Code: Alles auswählen
Ein EXPLAIN ANALYZE ergibt folgenden Output (Lauf 2)
"Bitmap Heap Scan on product  (cost=74.84..3134.82 rows=814 width=37) (actual time=80.682..85.084 rows=197 loops=1)"
"  Recheck Cond: (searchindex @@ '''badezusatz'''::tsquery)"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..74.64 rows=814 width=0) (actual time=57.649..57.649 rows=1003 loops=1)"
"        Index Cond: (searchindex @@ '''badezusatz'''::tsquery)"
"Total runtime: 85.439 ms"



Kann mir jemand sagen, warum das erstmalige SELECT länger dauert, wie die darauffolgenden SELECTS?
Kann ich etwas verändern, um die Performance hier zu erhöhen?

Ich nutze Postgres 9.1 auf einem Ubuntu Server.

Schonmal vielen Dank!
pg_anfaenger
Neuer Benutzer
 
Beiträge: 8
Registriert: Di 3. Jul 2012, 10:26

Beitragvon akretschmer » Di 3. Jul 2012, 10:42

pg_anfaenger hat geschrieben:Kann mir jemand sagen, warum das erstmalige SELECT länger dauert, wie die darauffolgenden SELECTS?
Kann ich etwas verändern, um die Performance hier zu erhöhen?

Ich nutze Postgres 9.1 auf einem Ubuntu Server.

Schonmal vielen Dank!


Mach mal ein "explain (analyse, buffers) select ..." und vergleiche die Buffers-Werte ...


Andreas
--
ads Das hatte dir akretschmer gestern schon gesagt und siehe da sobald du das machst, funktioniert es ;-)

https://www.xing.com/profile/Andreas_Kretschmer7
Hosting-Provider mit PostgreSQL-Support gesucht? Mich fragen!
akretschmer
Erfahrener Benutzer
 
Beiträge: 5938
Registriert: So 29. Okt 2006, 14:35
Wohnort: Kaufbach, Sachsen, Germany, Germany

Beitragvon pg_anfaenger » Di 3. Jul 2012, 10:52

akretschmer hat geschrieben:Mach mal ein "explain (analyse, buffers) select ..." und vergleiche die Buffers-Werte ...


Andreas


wow das nenn ich mal eine schnelle Antwort!

SELECT 1:
EXPLAIN (ANALYZE on, BUFFERS on) select title from product where searchindex @@ to_tsquery('german', 'Anzug');
Code: Alles auswählen
"Bitmap Heap Scan on product  (cost=232.63..9415.68 rows=2593 width=37) (actual time=1718.576..10153.151 rows=3003 loops=1)"
"  Recheck Cond: (searchindex @@ '''anzug'''::tsquery)"
"  Buffers: shared hit=14274 read=8944"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..231.98 rows=2593 width=0) (actual time=1688.263..1688.263 rows=4312 loops=1)"
"        Index Cond: (searchindex @@ '''anzug'''::tsquery)"
"        Buffers: shared read=4512"
"Total runtime: 10160.156 ms"


SELECT 2:
EXPLAIN (ANALYZE on, BUFFERS on) select title from product where searchindex @@ to_tsquery('german', 'Anzug');
Code: Alles auswählen
"Bitmap Heap Scan on product  (cost=232.63..9415.68 rows=2593 width=37) (actual time=73.662..167.399 rows=3003 loops=1)"
"  Recheck Cond: (searchindex @@ '''anzug'''::tsquery)"
"  Buffers: shared hit=14259 read=8959"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..231.98 rows=2593 width=0) (actual time=73.112..73.112 rows=4312 loops=1)"
"        Index Cond: (searchindex @@ '''anzug'''::tsquery)"
"        Buffers: shared read=4512"
"Total runtime: 175.899 ms"


pg_anfaenger
Neuer Benutzer
 
Beiträge: 8
Registriert: Di 3. Jul 2012, 10:26

Beitragvon akretschmer » Di 3. Jul 2012, 10:59

pg_anfaenger hat geschrieben:wow das nenn ich mal eine schnelle Antwort!


Hrm. Das ist nicht das, was ich erwartet hatte. Oder vielleicht doch. Jedenfalls denke ich, das ist ein Problem eines 'kalten Caches'. Der Index-Scan hat 4512 'shared read', beide Male. Beim 2.Mal aber hat das OS es im Cache und muß es nicht von Platte hobeln. Wie sind Deine Einstellungen shared_buffers, wie viel RAM hat die Maschine?


Andreas
--
ads Das hatte dir akretschmer gestern schon gesagt und siehe da sobald du das machst, funktioniert es ;-)

https://www.xing.com/profile/Andreas_Kretschmer7
Hosting-Provider mit PostgreSQL-Support gesucht? Mich fragen!
akretschmer
Erfahrener Benutzer
 
Beiträge: 5938
Registriert: So 29. Okt 2006, 14:35
Wohnort: Kaufbach, Sachsen, Germany, Germany

Beitragvon pg_anfaenger » Di 3. Jul 2012, 11:04

Der Server (V-Server) hat 2048 Megabyte garantiertes RAM und dynamisch kann es auf 4096 Megabyte hochgehen

Habe an den Postgres Einstellungen nichts verändert.

Code: Alles auswählen
#------------------------------------------------------------------------------
# RESOURCE USAGE (except WAL)
#------------------------------------------------------------------------------


# - Memory -


shared_buffers = 24MB            # min 128kB
                    # (change requires restart)
#temp_buffers = 8MB            # min 800kB
#max_prepared_transactions = 0        # zero disables the feature
                    # (change requires restart)
# Note:  Increasing max_prepared_transactions costs ~600 bytes of shared memory
# per transaction slot, plus lock space (see max_locks_per_transaction).
# It is not advisable to set max_prepared_transactions nonzero unless you
# actively intend to use prepared transactions.
#work_mem = 1MB                # min 64kB
#maintenance_work_mem = 16MB        # min 1MB
#max_stack_depth = 2MB            # min 100kB


# - Kernel Resource Usage -


#max_files_per_process = 1000        # min 25
                    # (change requires restart)
#shared_preload_libraries = ''        # (change requires restart)


# - Cost-Based Vacuum Delay -


#vacuum_cost_delay = 0ms        # 0-100 milliseconds
#vacuum_cost_page_hit = 1        # 0-10000 credits
#vacuum_cost_page_miss = 10        # 0-10000 credits
#vacuum_cost_page_dirty = 20        # 0-10000 credits
#vacuum_cost_limit = 200        # 1-10000 credits


# - Background Writer -


#bgwriter_delay = 200ms            # 10-10000ms between rounds
#bgwriter_lru_maxpages = 100        # 0-1000 max buffers written/round
#bgwriter_lru_multiplier = 2.0        # 0-10.0 multipler on buffers scanned/round


# - Asynchronous Behavior -


#effective_io_concurrency = 1        # 1-1000. 0 disables prefetching
pg_anfaenger
Neuer Benutzer
 
Beiträge: 8
Registriert: Di 3. Jul 2012, 10:26

Beitragvon akretschmer » Di 3. Jul 2012, 11:10

pg_anfaenger hat geschrieben:Der Server (V-Server) hat 2048 Megabyte garantiertes RAM und dynamisch kann es auf 4096 Megabyte hochgehen

Habe an den Postgres Einstellungen nichts verändert.


Setze shared_buffers hoch. Bei 2 GB RAM (und die Kiste nur PG-Server macht) ruhig auf 256MB. work_mem auch anheben, wobei das bei Deinem Selekt nicht das Problem war/ist.

Andreas
--
ads Das hatte dir akretschmer gestern schon gesagt und siehe da sobald du das machst, funktioniert es ;-)

https://www.xing.com/profile/Andreas_Kretschmer7
Hosting-Provider mit PostgreSQL-Support gesucht? Mich fragen!
akretschmer
Erfahrener Benutzer
 
Beiträge: 5938
Registriert: So 29. Okt 2006, 14:35
Wohnort: Kaufbach, Sachsen, Germany, Germany

Beitragvon pg_anfaenger » Di 3. Jul 2012, 11:23

Ich kann die DB leider nach dem Ändern des shared_buffers nicht mehr starten:
Code: Alles auswählen
 * Restarting PostgreSQL 9.1 database server                                   
 * The PostgreSQL server failed to start. Please check the log output:
2012-07-03 11:22:07 CEST FATAL:  could not create shared memory segment: Das Argument ist ung?ltig
2012-07-03 11:22:07 CEST DETAIL:  Failed system call was shmget(key=5432001, size=224116736, 03600).
2012-07-03 11:22:07 CEST HINT:  This error usually means that PostgreSQL's request for a shared memory segment exceeded your kernel's SHMMAX parameter.  You can either reduce the request size or reconfigure the kernel with larger SHMMAX.  To reduce the request size (currently 224116736 bytes), reduce PostgreSQL's shared memory usage, perhaps by reducing shared_buffers or max_connections.
   If the request size is already small, it's possible that it is less than your kernel's SHMMIN parameter, in which case raising the request size or reconfiguring SHMMIN is called for.
   The PostgreSQL documentation contains more information about shared memory configuration.
                                                                         [fail]

pg_anfaenger
Neuer Benutzer
 
Beiträge: 8
Registriert: Di 3. Jul 2012, 10:26

Beitragvon akretschmer » Di 3. Jul 2012, 11:29

pg_anfaenger hat geschrieben:Ich kann die DB leider nach dem Ändern des shared_buffers nicht mehr starten:
Code: Alles auswählen

2012-07-03 11:22:07 CEST HINT:  This error usually means that PostgreSQL's request for a shared memory segment exceeded your kernel's SHMMAX parameter. 


Let me google that for you

Andreas
--
ads Das hatte dir akretschmer gestern schon gesagt und siehe da sobald du das machst, funktioniert es ;-)

https://www.xing.com/profile/Andreas_Kretschmer7
Hosting-Provider mit PostgreSQL-Support gesucht? Mich fragen!
akretschmer
Erfahrener Benutzer
 
Beiträge: 5938
Registriert: So 29. Okt 2006, 14:35
Wohnort: Kaufbach, Sachsen, Germany, Germany

Beitragvon pg_anfaenger » Di 3. Jul 2012, 11:52

Habe jetzt die Shared Buffer auf 240MB hochgesetzt, aber leider ohne wirkliche Verbesserung:
Code: Alles auswählen
"Bitmap Heap Scan on product  (cost=44.61..9909.00 rows=2660 width=34) (actual time=366.109..26321.597 rows=3512 loops=1)"
"  Recheck Cond: (searchindex @@ '''anzug'''::tsquery)"
"  Buffers: shared hit=1 read=2212"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..43.95 rows=2660 width=0) (actual time=325.746..325.746 rows=3707 loops=1)"
"        Index Cond: (searchindex @@ '''anzug'''::tsquery)"
"        Buffers: shared hit=1 read=8"
"Total runtime: 26324.789 ms"


Code: Alles auswählen
"Bitmap Heap Scan on product  (cost=44.61..9909.00 rows=2660 width=34) (actual time=4.145..19.458 rows=3512 loops=1)"
"  Recheck Cond: (searchindex @@ '''anzug'''::tsquery)"
"  Buffers: shared hit=2213"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..43.95 rows=2660 width=0) (actual time=3.129..3.129 rows=3707 loops=1)"
"        Index Cond: (searchindex @@ '''anzug'''::tsquery)"
"        Buffers: shared hit=9"
"Total runtime: 22.387 ms"
pg_anfaenger
Neuer Benutzer
 
Beiträge: 8
Registriert: Di 3. Jul 2012, 10:26

Beitragvon akretschmer » Di 3. Jul 2012, 12:01

pg_anfaenger hat geschrieben:Habe jetzt die Shared Buffer auf 240MB hochgesetzt, aber leider ohne wirkliche Verbesserung:
Code: Alles auswählen
"Bitmap Heap Scan on product  (cost=44.61..9909.00 rows=2660 width=34) (actual time=366.109..26321.597 rows=3512 loops=1)"
"  Recheck Cond: (searchindex @@ '''anzug'''::tsquery)"
"  Buffers: shared hit=1 read=2212"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..43.95 rows=2660 width=0) (actual time=325.746..325.746 rows=3707 loops=1)"
"        Index Cond: (searchindex @@ '''anzug'''::tsquery)"
"        Buffers: shared hit=1 read=8"
"Total runtime: 26324.789 ms"


Code: Alles auswählen
"Bitmap Heap Scan on product  (cost=44.61..9909.00 rows=2660 width=34) (actual time=4.145..19.458 rows=3512 loops=1)"
"  Recheck Cond: (searchindex @@ '''anzug'''::tsquery)"
"  Buffers: shared hit=2213"
"  ->  Bitmap Index Scan on searchindex_idx  (cost=0.00..43.95 rows=2660 width=0) (actual time=3.129..3.129 rows=3707 loops=1)"
"        Index Cond: (searchindex @@ '''anzug'''::tsquery)"
"        Buffers: shared hit=9"
"Total runtime: 22.387 ms"



Nun, aber bei der ersten Abfrage ist "Buffers: shared hit=1 read=2212", bei der 2ten dann "Buffers: shared hit=2213". Auch beim Index Scan sieht man, daß im 2. Versuch alles aus dem shared_buffers komt, während beim ersten Versuch von Platte zu lesen ist.

RAM ist nun mal nicht zu ersetzen. Höchstens mit mehr RAM. Und wenn die Daten in den shared_buffers sind, sind sie 'näher' an der DB als in Plattencaches des OS.

Mit 256 MB für shared_buffers ist das natürlich auch noch nicht viel, aber ich weiß auch nicht, wie groß die DB insgesamt ist. Bei vServern sollte man auch keine übertriebenen Erwartungen in die Plattenperformance setzen.

Andreas
--
ads Das hatte dir akretschmer gestern schon gesagt und siehe da sobald du das machst, funktioniert es ;-)

https://www.xing.com/profile/Andreas_Kretschmer7
Hosting-Provider mit PostgreSQL-Support gesucht? Mich fragen!
akretschmer
Erfahrener Benutzer
 
Beiträge: 5938
Registriert: So 29. Okt 2006, 14:35
Wohnort: Kaufbach, Sachsen, Germany, Germany

Nächste

Zurück zu Allgemeines

Wer ist online?

Mitglieder in diesem Forum: 0 Mitglieder und 0 Gäste

cron