[PERFORM] Postgresql, and ODBC handles - Mailing list pgsql-performance

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