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:
Realusersys
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