profiling pgbench

I did some profiling of pgbench -j 36 -c 36 -T 500 banging on my
two-core desktop box - with synchronous_commit turned off to keep the
fsyncs from dominating the profile - and got these results:

29634     4.7124  postgres                 base_yyparse
27906     4.4377  postgres                 AllocSetAlloc
17751     2.8228  postgres                 SearchCatCache
13029     2.0719  postgres                 hash_search_with_hash_value
11253     1.7895  postgres                 core_yylex
9957      1.5834  libc-2.11.2.so           memcmp
9237      1.4689  libc-2.11.2.so           __strcmp_sse2
8628      1.3720  postgres                 ScanKeywordLookup
7984      1.2696  postgres                 GetSnapshotData
7144      1.1361  postgres                 MemoryContextAllocZeroAligned
6898      1.0969  postgres                 XLogInsert
6440      1.0241  postgres                 LWLockAcquire

Full report and call graph attached.  The opannotate results are 2MB
bzip'd, so I'm not attaching those; send me an email off-list if you
want them.

I'd like to get access to a box with (a lot) more cores, to see
whether the lock stuff moves up in the profile.  A big chunk of that
hash_search_with_hash_value overhead is coming from
LockAcquireExtended.  The __strcmp_sse2 is almost entirely parsing
overhead.  In general, I'm not sure there's much hope for reducing the
parsing overhead, although ScanKeywordLookup() can certainly be done
better.  XLogInsert() is spending a lot of time doing CRC's.
LWLockAcquire() is dropping cycles in many different places.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company