On 2/9/17 7:15 PM, Jim Nasby wrote: > Can you run a trace to see where all the time is going in the single row > case? I don't see an obvious time-suck with a quick look through the code. > It'd be interesting to see how things change if you eliminate the filler > column from the SELECT.
Traces are attached, these are with callgrind.
profile_nofiller.txt: single row without filler column
profile_filler.txt: single row with filler column
profile_filler_callback.txt: callback with filler column
pqResultAlloc looks to hit malloc pretty hard. The callback reduces all of
that to a single malloc for each row.
Without the filler, here is the average over 11 runs:
Real user sys
Callback .133 .033 .035
Single Row .170 .112 .029
For the callback case, it's slightly higher than the prior results with the
filler column.
--------------------------------------------------------------------------------
Profile data file 'callgrind.out.14930' (creator: callgrind-3.11.0)
--------------------------------------------------------------------------------
I1 cache:
D1 cache:
LL cache:
Timerange: Basic block 0 - 74120972
Trigger: Program termination
Profiled target: ./test -m row (PID 14930, part 1)
Events recorded: Ir
Events shown: Ir
Event sort order: Ir
Thresholds: 99
Include dirs:
User annotated:
Auto-annotation: off
--------------------------------------------------------------------------------
Ir
--------------------------------------------------------------------------------
313,455,690 PROGRAM TOTALS
--------------------------------------------------------------------------------
Ir file:function
--------------------------------------------------------------------------------
61,410,828 ???:_int_malloc [/usr/lib64/libc-2.17.so]
38,321,887 ???:_int_free [/usr/lib64/libc-2.17.so]
25,800,115 ???:pqResultAlloc [/usr/local/pgsql/lib/libpq.so.5.10]
20,611,330 ???:pqParseInput3 [/usr/local/pgsql/lib/libpq.so.5.10]
16,002,817 ???:malloc [/usr/lib64/libc-2.17.so]
14,800,004 ???:pqRowProcessor [/usr/local/pgsql/lib/libpq.so.5.10]
12,604,893 ???:pqGetInt [/usr/local/pgsql/lib/libpq.so.5.10]
10,400,004 ???:PQsetResultAttrs [/usr/local/pgsql/lib/libpq.so.5.10]
10,200,316 main.c:main [/usr/local/src/postgresql-perf/test]
9,600,000 ???:check_tuple_field_number [/usr/local/pgsql/lib/libpq.so.5.10]
8,300,631 ???:__strcpy_sse2_unaligned [/usr/lib64/libc-2.17.so]
7,500,075 ???:pqResultStrdup [/usr/local/pgsql/lib/libpq.so.5.10]
7,500,000 ???:pqSkipnchar [/usr/local/pgsql/lib/libpq.so.5.10]
7,017,368 ???:__memcpy_ssse3_back [/usr/lib64/libc-2.17.so]
6,900,000 ???:PQgetisnull [/usr/local/pgsql/lib/libpq.so.5.10]
6,401,100 ???:free [/usr/lib64/libc-2.17.so]
6,200,004 ???:PQcopyResult [/usr/local/pgsql/lib/libpq.so.5.10]
6,100,959 ???:__strlen_sse2_pminub [/usr/lib64/libc-2.17.so]
5,700,000 ???:PQgetvalue [/usr/local/pgsql/lib/libpq.so.5.10]
4,700,045 ???:PQclear [/usr/local/pgsql/lib/libpq.so.5.10]
4,200,057 ???:PQmakeEmptyPGresult [/usr/local/pgsql/lib/libpq.so.5.10]
4,103,903 ???:PQgetResult [/usr/local/pgsql/lib/libpq.so.5.10]
3,400,000 ???:pqAddTuple [/usr/local/pgsql/lib/libpq.so.5.10]
3,203,437 ???:pqGetc [/usr/local/pgsql/lib/libpq.so.5.10]
2,600,034 ???:pqPrepareAsyncResult [/usr/local/pgsql/lib/libpq.so.5.10]
2,500,679 ???:appendBinaryPQExpBuffer [/usr/local/pgsql/lib/libpq.so.5.10]
2,300,621 ???:enlargePQExpBuffer [/usr/local/pgsql/lib/libpq.so.5.10]
1,600,016 ???:appendPQExpBufferStr [/usr/local/pgsql/lib/libpq.so.5.10]
900,270 ???:resetPQExpBuffer [/usr/local/pgsql/lib/libpq.so.5.10]
--------------------------------------------------------------------------------
Profile data file 'callgrind.out.15062' (creator: callgrind-3.11.0)
--------------------------------------------------------------------------------
I1 cache:
D1 cache:
LL cache:
Timerange: Basic block 0 - 84068364
Trigger: Program termination
Profiled target: ./test -m row (PID 15062, part 1)
Events recorded: Ir
Events shown: Ir
Event sort order: Ir
Thresholds: 99
Include dirs:
User annotated:
Auto-annotation: off
--------------------------------------------------------------------------------
Ir
--------------------------------------------------------------------------------
358,525,458 PROGRAM TOTALS
--------------------------------------------------------------------------------
Ir file:function
--------------------------------------------------------------------------------
61,410,901 ???:_int_malloc [/usr/lib64/libc-2.17.so]
38,321,887 ???:_int_free [/usr/lib64/libc-2.17.so]
31,400,139 ???:pqResultAlloc [/usr/local/pgsql/lib/libpq.so.5.10]
22,839,505 ???:pqParseInput3 [/usr/local/pgsql/lib/libpq.so.5.10]
17,600,004 ???:pqRowProcessor [/usr/local/pgsql/lib/libpq.so.5.10]
16,002,817 ???:malloc [/usr/lib64/libc-2.17.so]
14,716,359 ???:pqGetInt [/usr/local/pgsql/lib/libpq.so.5.10]
14,400,000 ???:check_tuple_field_number [/usr/local/pgsql/lib/libpq.so.5.10]
13,800,324 main.c:main [/usr/local/src/postgresql-perf/test]
12,300,004 ???:PQsetResultAttrs [/usr/local/pgsql/lib/libpq.so.5.10]
12,289,332 ???:__memcpy_ssse3_back [/usr/lib64/libc-2.17.so]
11,100,653 ???:__strcpy_sse2_unaligned [/usr/lib64/libc-2.17.so]
10,000,100 ???:pqResultStrdup [/usr/local/pgsql/lib/libpq.so.5.10]
10,000,000 ???:pqSkipnchar [/usr/local/pgsql/lib/libpq.so.5.10]
9,200,000 ???:PQgetisnull [/usr/local/pgsql/lib/libpq.so.5.10]
8,500,969 ???:__strlen_sse2_pminub [/usr/lib64/libc-2.17.so]
7,600,000 ???:PQgetvalue [/usr/local/pgsql/lib/libpq.so.5.10]
6,401,100 ???:free [/usr/lib64/libc-2.17.so]
6,200,004 ???:PQcopyResult [/usr/local/pgsql/lib/libpq.so.5.10]
4,700,045 ???:PQclear [/usr/local/pgsql/lib/libpq.so.5.10]
4,200,057 ???:PQmakeEmptyPGresult [/usr/local/pgsql/lib/libpq.so.5.10]
4,114,703 ???:PQgetResult [/usr/local/pgsql/lib/libpq.so.5.10]
3,400,000 ???:pqAddTuple [/usr/local/pgsql/lib/libpq.so.5.10]
3,212,077 ???:pqGetc [/usr/local/pgsql/lib/libpq.so.5.10]
2,600,034 ???:pqPrepareAsyncResult [/usr/local/pgsql/lib/libpq.so.5.10]
2,500,704 ???:appendBinaryPQExpBuffer [/usr/local/pgsql/lib/libpq.so.5.10]
2,300,644 ???:enlargePQExpBuffer [/usr/local/pgsql/lib/libpq.so.5.10]
2,200,000 ???:PQgetlength [/usr/local/pgsql/lib/libpq.so.5.10]
1,600,016 ???:appendPQExpBufferStr [/usr/local/pgsql/lib/libpq.so.5.10]
900,279 ???:resetPQExpBuffer [/usr/local/pgsql/lib/libpq.so.5.10]
--------------------------------------------------------------------------------
Profile data file 'callgrind.out.15112' (creator: callgrind-3.11.0)
--------------------------------------------------------------------------------
I1 cache:
D1 cache:
LL cache:
Timerange: Basic block 0 - 18844066
Trigger: Program termination
Profiled target: ./test -m cb (PID 15112, part 1)
Events recorded: Ir
Events shown: Ir
Event sort order: Ir
Thresholds: 99
Include dirs:
User annotated:
Auto-annotation: off
--------------------------------------------------------------------------------
Ir
--------------------------------------------------------------------------------
84,800,453 PROGRAM TOTALS
--------------------------------------------------------------------------------
Ir file:function
--------------------------------------------------------------------------------
16,842,303 ???:pqParseInput3 [/usr/local/pgsql/lib/libpq.so.5.10]
14,810,783 ???:_int_malloc [/usr/lib64/libc-2.17.so]
12,616,338 ???:pqGetInt [/usr/local/pgsql/lib/libpq.so.5.10]
10,000,000 ???:pqSkipnchar [/usr/local/pgsql/lib/libpq.so.5.10]
9,200,004 main.c:process_callback [/usr/local/src/postgresql-perf/test]
7,305,178 ???:_int_free [/usr/lib64/libc-2.17.so]
4,002,817 ???:malloc [/usr/lib64/libc-2.17.so]
2,600,000 ???:pqRowProcessor [/usr/local/pgsql/lib/libpq.so.5.10]
2,296,178 ???:__memcpy_ssse3_back [/usr/lib64/libc-2.17.so]
1,612,027 ???:pqGetc [/usr/local/pgsql/lib/libpq.so.5.10]
1,601,100 ???:free [/usr/lib64/libc-2.17.so]
800,284 main.c:main [/usr/local/src/postgresql-perf/test]
600,000 /usr/include/bits/byteswap.h:process_callback
Performance Results.xlsx
Description: Performance Results.xlsx
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
