Różnica w czasie wykonania zapytania pomiędzy EXPLAIN ANALYSE a rzeczywistym zapytaniem

0

Spójrzcie na ten query plan:

QUERY PLAN
HashAggregate  (cost=66.50..67.87 rows=137 width=9) (actual time=1.923..1.940 rows=51 loops=1)
  Group Key: user_id, robot
  Buffers: shared hit=31
  ->  Seq Scan on sessions  (cost=0.00..56.25 rows=1366 width=9) (actual time=0.017..1.227 rows=1360 loops=1)
        Filter: ((path)::text ~~ '/forum/%'::text)
        Rows Removed by Filter: 660
        Buffers: shared hit=31
Planning time: 0.860 ms
Execution time: 1.988 ms

Spójrzcie na: Execution time: 1.988 ms

Teraz wykonując zapytanie bez EXPLAIN ANALYSE na początku: 50 rows retrieved starting from 1 in 98ms (execution: 87ms, fetching: 11ms)

Wykonanie zapytania trwało aż 87ms. Skąd ta różnica?

SQL:

SELECT
 "user_id", "robot", COUNT(*)
FROM
 "sessions"
WHERE
 "path" LIKE '/forum/%'
GROUP
 BY "user_id", "robot"

DDL

create table sessions
(
	id varchar(255) not null,
	user_id integer,
	robot varchar(255),
	path varchar(1000)
)
;
            Table "public.sessions"
 Column  |          Type           | Modifiers
---------+-------------------------+-----------
 id      | character varying(255)  | not null
 user_id | integer                 |
 robot   | character varying(255)  |
 path    | character varying(1000) |
Indexes:
    "sessions_path_index" btree (path text_pattern_ops)
0

https://stackoverflow.com/a/33553669

Ja bym się w ogóle nie kierował czasami tylko raczej statystykami - liczba I/O lub dotkniętych wierszy.
Zresztą, podaj SQL-a bo to takie rozmawianie nie wiadomo o czym.

0
vpiotr napisał(a):

https://stackoverflow.com/a/33553669

Hmm, jeżeli dobrze rozumiem, w tym pytaniu chodzi o różnicę pomiędzy "planning time" a "execution time".

Mi natomiast chodzi o to, że nie wiem czemu moje zapytanie wykonuje się tak długo (prawie 100ms) podczas gdy Postgres twierdzi (poprzez zapytanie EXPLAIN ANALYSE), że czas wykonania tego zapytania to powinno być ~2 ms. Tabela jest mała, ledwie 2k rekordów, więc zapytanie powinno wykonywać się w mig.

0

OK, to wg mnie głównym winowajcą jest sekwencyjne skanowanie (całej tablicy).
Jeśli dobrze czytam ten plan to:

  • w tablicy masz 1366 rekordów (wszystkie czytane)
  • odpadło 660
  • do grupowania wziął ok. 700
  • zwrócił 137 grup

Jeśli to się nie zgadza z realnym wykonaniem to może być odpowiedź dlaczego masz różnicę w czasach.

0

@vpiotr: racja, nie zgadza się. Liczba zwróconych wierszy jest mniejsza niż 130 (dwukrotnie). W tabeli jest indeks na kolumnie path ale domyślam się że tabela jest zbyt mała i postgres wybiera skanowanie sekwencyjne.

0

@Adam Boduch:

The \timing command will show you the total time it took to execute your query, and fetch the results back to the client.
EXPLAIN ANALYZE, on the other hand, will show you the total time to execute your query on the server, not including the overhead of fetching results.

0

@Desu: jasna sprawa. Zobacz mój pierwszy post. Napisałem tam: 50 rows retrieved starting from 1 in 98ms (execution: 87ms, fetching: 11ms) Z tego wynika, że "fetching" to jedynie 11 ms, natomiast "execution" to aż 87ms.

Może jednak robię z igły widły. Zalogowałem się poprzez ssh i wykonałem to samo zapytanie bezpośrednio z konsoli i zapytanie wykonuje się w 5 ms ;] Czyli dobrze. Natomiast wykonując z IDE czas jest taki jak powyżej.

Natomiast newrelic podaje:

screenshot-20170811105941.png

Czyli też mówi, że zapytanie średnio wykonuje się 100 ms. I bądź tu mądry....

0

Nie jestem bazodanowym ninją, ale czy te dodatkowe ms to nie czas potrzebny na startup/shutdown sesji? Cholera wie, jak sie dowiesz to daj znac :P

0

Jak masz indeks do tego wyszukiwania to spróbuj zrobić ANALYZE na tej tabeli.
https://www.postgresql.org/docs/9.2/static/sql-analyze.html

0

Wygląda na to, że wynik "execution time" jest zakłamany przez to, że łączę się z bazą zdalnie. Lokalnie, to zapytanie wykonuje się o wiele, wiele szybciej. Nie wiem czemu tylko newreli podaje taki zakłamany wynik (to mnie zmyliło).

1 użytkowników online, w tym zalogowanych: 0, gości: 1