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

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:


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:

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

select title from product where searchindex @@ to_tsquery('german', 'Badezusatz');

Ein EXPLAIN ANALYZE ergibt folgenden Output (Lauf 1)

"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"



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!

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’);

"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’);

"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"

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

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.

#------------------------------------------------------------------------------
# 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

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

Ich kann die DB leider nach dem Ändern des shared_buffers nicht mehr starten:

 * 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]

Let me google that for you

Andreas

Habe jetzt die Shared Buffer auf 240MB hochgesetzt, aber leider ohne wirkliche Verbesserung:

"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"
"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

ok. soweit - sogut.
Aber: Schafft man es auch die erste Abfrage zu beschleunigen? In meinem ersten Post mit den ANALYSE on, Buffers on Daten sieht man ja, das die Shared-Buffer Anzahl nahezu identisch ist, aber die Abfrage beim ersten mal trotzdem um ein vielfaches länger dauert!?

Schonmal vielen vielen Dank für die Hilfe!!!

Unterscheide zwischen shared hit und shared read. Im übrigen ist die Abfrage deutlich schneller geworden jetzt im Vergleich ganz am Anfang, stimmts?

Wenn die Daten erst mal im RAM sind, geht es schneller, ganz normal. Und so ein PG-Server läuft doch für länger, die Situation mit dem kalten Cache hast Du doch nur ein mal: nach dem Start.


Andreas

ok danke. das ganze liefert mir beim ersten aufruf aber trotzdem keine wirklich zufrieden stellenden ergbenisse.
habe meine suche jetzt auf lucene umgestellt, mit der doch wesentlich bessere ergebnisse erreicht werden.

hrhr Nutzen wir mal eben ein anderes Tool :wink:
Wobei Lucene die bessere Wahl aufgrund der besseren Volltextsuche ist.

Wenn du wirklich auch die erste Anfrage beschleunigen willst, kannst du die Daten schon mal als Vorrat in den Speicher laden - einfach nach dem Start die Anfrage schon mal ausführen.

das ist aber auch nicht wirklich schön, da ich dann verschiedene “dummy” selects reinladen muss und sobald der server durchgestartet wird wieder einen leeren chache habe.

bin mit der lucene performance bis jetzt zufrieden.