Summary: I am facing a contention problem with ODBC on the client side. strace
and perf top show we are serializing over what appears to be accesses to the
ODBC statement handle. Contention goes down if I use multiple processes instead
of multiple threads within a process. Also, all the threads get the same
connection handle number and the same statement handle number. Is there a way
to force different connection and statement handles? I have asked this question
on the ODBC mailing list, and they suggested it could be something in the
postgresql driver.
Details: Running the TPCx-V benchmark, we hit a performance bottleneck as the
load increases. We have plenty of CPU and disk resources available in our
driver VM, client VM, and database backend VM (all with high vCPU counts) on a
dedicated server. When we increase the number of threads of execution, not only
doesn’t throughput go up, it actually degrades. I am running with 80 threads in
one process. When I divide these threads into 5 processes, performance nearly
doubles. So, the problem is not in the database backend. Each thread has its
own database connection and its own statement handle.
Looking more closely at the client, this is what I see in the strace output
when everything flows through one process:
17:52:52.762491 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000102>
17:52:52.762635 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= 0 <0.000664>
17:52:52.763540 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000027>
17:52:52.763616 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000076>
17:52:52.763738 futex(0x7fae463a9f00, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000016>
17:52:52.763793 futex(0x7fae463a9f00, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000010>
17:52:52.763867 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000038>
17:52:52.763982 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000037>
17:52:52.764078 futex(0x7fae18000020, FUTEX_WAKE_PRIVATE, 1)
= 0 <0.000010>
17:52:52.764182 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000030>
17:52:52.764264 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000075>
17:52:52.764401 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000014>
17:52:52.764455 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000011>
17:52:52.764507 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000025>
17:52:52.764579 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000010>
17:52:52.764821 sendto(227, "\x51\x00\x00\x00\x0b\x43\x4f\x4d\x4d\x49\x54\x00",
12, MSG_NOSIGNAL, NULL, 0) = 12 <0.000029>
17:52:52.764911 recvfrom(227, 0x7fae18058760, 4096, 16384, 0, 0)
= -1 EAGAIN (Resource temporarily unavailable) <0.000107>
17:52:52.765065 poll([{fd=227, events=POLLIN}], 1, 4294967295)
= 1 ([{fd=227, revents=POLLIN}]) <0.000017>
17:52:52.765185 recvfrom(227,
"\x43\x00\x00\x00\x0b\x43\x4f\x4d\x4d\x49\x54\x00\x5a\x00\x00\x00\x05\x49",
4096, MSG_NOSIGNAL, NULL, NULL) = 18 <0.000018>
17:52:52.765258 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= 0 <0.000470>
17:52:52.765764 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000052>
17:52:52.765908 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000073>
17:52:52.766045 futex(0x7fae351c5100, FUTEX_WAKE_PRIVATE, 1)
= 1 <0.000040>
17:52:52.766246 futex(0x7fae351c5100, FUTEX_WAIT_PRIVATE, 2, NULL)
= -1 EAGAIN (Resource temporarily unavailable) <0.000026>
And perf top shows:
9.89% [kernel] [k] _raw_spin_unlock_irqrestore
4.86% [kernel] [k] finish_task_switch
3.53% [kernel] [k] _raw_spin_lock
3.00% libodbc.so.2.0.0 [.] __check_stmt_from_dbc_v
2.80% [kernel] [k] __do_softirq
2.43% psqlodbcw.so [.] 0x000000000003b146
1.95% libodbc.so.2.0.0 [.] __validate_stmt
1.93% libc-2.17.so [.] _IO_vfscanf
1.91% libodbc.so.2.0.0 [.] __validate_dbc
1.90% psqlodbcw.so [.] copy_and_convert_field
1.80% libc-2.17.so [.] _int_malloc
1.58% libc-2.17.so [.] malloc
1.42% libc-2.17.so [.] _int_free
1.36% libodbc.so.2.0.0 [.] __release_desc
1.26% libc-2.17.so [.] __strncpy_sse2_unaligned
1.25% psqlodbcw.so [.] mylog
1.17% libc-2.17.so [.] __offtime
1.05% [kernel] [k] vmxnet3_xmit_frame
1.03% psqlodbcw.so [.] SC_fetch
0.91% libc-2.17.so [.] __memcpy_ssse3_back
0.89% libc-2.17.so [.] __strcpy_sse2_unaligned
0.87% libc-2.17.so [.] __GI_____strtod_l_internal
0.86% libc-2.17.so [.] __tz_convert
0.76% libc-2.17.so [.] __tzfile_compute
0.76% psqlodbcw.so [.] convert_linefeeds
0.71% libpthread-2.17.so [.] pthread_mutex_lock
0.69% [kernel] [k] vmxnet3_poll_rx_only
0.66% [kernel] [k] tick_nohz_idle_enter
0.64% libc-2.17.so [.] __strcmp_sse2
0.63% libc-2.17.so [.] malloc_consolidate
0.63% libodbc.so.2.0.0 [.] __set_stmt_state
0.62% [kernel] [k] __audit_syscall_exit
0.60% libc-2.17.so [.] __GI_____strtoll_l_internal
0.59% libc-2.17.so [.] __memset_sse2
0.56% libpthread-2.17.so [.] pthread_mutex_unlock
0.54% psqlodbcw.so [.] PGAPI_ExtendedFetch
0.53% [kernel] [k] ipt_do_table
So, we have severe contention, but not over actual database accesses. If I look
at the PGSQL backend, I see many transactions in flight; i.e., transactions
aren’t serialized. The contention appears to be over accesses to data
structures:
- With 5 processes and 80 threads of execution, the response time of
the TRADE_STATUS transaction is 6.3ms @ 2718 total transactions/sec
- With 1 process and 80 threads of execution, TRADE_STATUS response
time is 44ms @ 1376 total transactions/sec
- TRADE_STATUS has a number of function calls that reference the
“stmt” handle returned by SQLAllocStmt:
o 6 to allocate the statement handle, run the query, bind input parameter,
free the handle, …
o 13 SQLBindCol()
o 50 SQLFetch()
- If I replace the 50 SQLFetch() calls with a single
SQLExtendedFetch() call, response time drops to 20ms
- If I comment out the 13 SQLBindCol() calls (which means the
benchmark isn’t working right but the query still runs), it drops to 13.9ms
- If by dropping these calls we were simply saving the execution time
of their pathlength, we would have saved at most the 6.3ms we measured with 5
processes. So, the improvements we saw by avoiding the SQLBindCol() and
SQLFetch() calls weren’t simply due to doing less work. They were due to
avoiding contention inside those routines
Something that puzzles me is that all the calls to
SQLAllocHandle(SQL_HANDLE_DBC, env_handle, &dbc_handle) set the dbc_handle to
19290 for all the threads within the process, and all the calls to
SQLAllocHandle(SQL_HANDLE_STMT, dbc_handle, &stmt_handle) set the stmt_handle
to 19291. Even if I call SQLAllocHandle(SQL_HANDLE_STMT, , ) multiple times to
get multiple statement handles, all the handles get set to the same 19291 (and
furthermore, performance gets worse even if I don’t use the new statement
handles; just creating them impacts performance).
Is there a way to avoid all this contention, and allow multiple threads to
behave like multiple processes? The threads do not share connections,
statements, etc. There should be no contention between them, and as far as I
can tell, there isn’t any contention over actual resources. The contention
appears to be over just accessing the ODBC data structures
We have unixODBC-2.3.4, built with:
./configure --prefix=/usr --sysconfdir=/etc --enable-threads=yes
--enable-drivers=yes --enable-driver-conf=yes --enable-stats=no
--enable-fastvalidate=yes
make
make install
My config files look like:
# cat /etc/odbcinst.ini
# Example driver definitions
# Driver from the postgresql-odbc package
# Setup from the unixODBC package
[PostgreSQL]
Description = ODBC for PostgreSQL
Driver = /usr/lib/psqlodbcw.so
Setup = /usr/lib/libodbcpsqlS.so
Driver64 = /usr/pgsql-9.3/lib/psqlodbcw.so
Setup64 = /usr/lib64/libodbcpsqlS.so
FileUsage = 1
Threading = 0
#
# cat /etc/odbc.ini
[PSQL2]
Description = PostgreSQL
Driver = PostgreSQL
Database = tpcv
ServerName = w1-tpcv-vm-50
UserName = tpcv
Password = tpcv
Port = 5432
[PSQL5]
Description = PostgreSQL
Driver = PostgreSQL
Database = tpcv1
ServerName = w1-tpcv-vm-60
UserName = tpcv
Password = tpcv
Port = 5432
