Slower hammerdb client perfomance on linux

[nml11c]

I'm running the same driver script from linux and windows, and getting two times lower NOPM(mssqls tpc-c test, not async). Both linux and windows have the same hardware. CPU governor on linux is in perfomance mode and there isn't any visible problems with cpu/memory/disk/network during the run.

Maybe there is some known issue with running hammerdb on linux that I should know about?

[sm-shaw]

Did you read the release notes? CH1 S1 https://www.hammerdb.com/docs/ch01s01.html

1.5.2. SQL Server on Linux: unixODBC's handle validation may become a performance bottleneck

Using the HammerDB client for SQL Server on Linux can be slower than the same client on Windows when using the default installed unixODBC drivers on many Linux distributions. As described in the SQL Server Programming Guidelines "When using the driver with highly multithreaded applications, unixODBC's handle validation may become a performance bottleneck. In such scenarios, significantly more performance may be obtained by compiling unixODBC with the --enable-fastvalidate option. However, beware that this may cause applications which pass invalid handles to ODBC APIs to crash instead of returning SQL_INVALID_HANDLE errors." Recompiling unixODBC with the --enable-fastvalidate option has been measured to improve client performance by 2X. Example configure options used to build unixODBC are shown as follows:

./configure --prefix=/usr/local/unixODBC --enable-gui=no --enable-drivers=no --enable-iconv
--with-iconv-char-enc=UTF8 --with-iconv-ucode-enc=UTF16LE --enable-threads=yes --enable-fastvalidate``

[nml11c]

Thank you! I haven't seen that.

I tried to compile it from source with parameters that you've mentioned, but nothing has changed, unfortunately.
I think I might be doing something wrong with other dependencies. This is what I did:

curl https://packages.microsoft.com/keys/microsoft.asc | apt-key add -
curl https://packages.microsoft.com/config/ubuntu/20.04/prod.list > /etc/apt/sources.list.d/mssql-release.list
apt-get update 
apt-get install -y msodbcsql17
configure --prefix=/usr/local/unixODBC --enable-gui=no --enable-drivers=no --enable-iconv
--with-iconv-char-enc=UTF8 --with-iconv-ucode-enc=UTF16LE --enable-threads=yes --enable-fastvalidate
make
make install

After this when I run hammerdb driver script, I get:

Failed to load tdbc::odbc - couldn't load file "libiodbc.so": libiodbc.so: cannot open shared object file: No such file or directory

So I've fixed it with installing headers:

sudo apt-get install -y unixodbc-dev

And after doing all of this, perfomance was as bad as it was. Have I missed something?

[greenhal]

If you install the odbc libraries into a non-default directory, you have to tell the process where to find them.
e.g.

export ODBCINI=/usr/local/unixODBC/etc/odbc.ini
export ODBCSYSINI=/usr/local/unixODBC/etc
export LD_LIBRARY_PATH=/usr/local/unixODBC/lib

You may have to update/build/(copy from /etc/odbcinst.ini) the odbc.ini file.
This way you don't need to uninstall the drivers from the apt-get install.

You can verify which driver is being used using lsof

[nml11c]

Thank you @greenhal, this moved me a step closer!

Currently I'm stuck at this error:

Connection to DRIVER=ODBC Driver 17 for SQL Server;SERVER=tcp:<ip>,1433;UID=<uid>;PWD=<pass> could not be established : [unixODBC][Driver Manager]Driver's SQLAllocHandle on SQL_HANDLE_HENV failed
(connecting to database)

Some info:

odbcinst -j
unixODBC 2.3.7
DRIVERS............: /usr/local/unixODBC/etc/odbcinst.ini
SYSTEM DATA SOURCES: /usr/local/unixODBC/etc/odbc.ini
FILE DATA SOURCES..: /usr/local/unixODBC/etc/ODBCDataSources
USER DATA SOURCES..: /usr/local/unixODBC/etc/odbc.ini
SQLULEN Size.......: 8
SQLLEN Size........: 8
SQLSETPOSIROW Size.: 8

cat /usr/local/unixODBC/etc/odbc.ini
[ODBC Driver 17 for SQL Server]
Driver=/usr/local/unixODBC/lib/libodbc.so

echo $ODBCINI
/usr/local/unixODBC/etc/odbc.ini
echo $ODBCSYSINI
/usr/local/unixODBC/etc
echo $LD_LIBRARY_PATH
/usr/local/unixODBC/lib

strace -t -f isql -v <>
30716 19:05:06 execve("/usr/bin/isql", ["isql", "-v", "<>", "<>", "<>"], 0x7ffda56aace0 /* 24 vars */) = 0
30716 19:05:06 brk(NULL)                = 0x13a3000
30716 19:05:06 arch_prctl(0x3001 /* ARCH_??? */, 0x7fff945dba50) = -1 EINVAL (Invalid argument)
30716 19:05:06 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/tls/haswell/x86_64/libodbc.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 stat("/usr/local/unixODBC/lib/tls/haswell/x86_64", 0x7fff945daca0) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/tls/haswell/libodbc.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 stat("/usr/local/unixODBC/lib/tls/haswell", 0x7fff945daca0) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/tls/x86_64/libodbc.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 stat("/usr/local/unixODBC/lib/tls/x86_64", 0x7fff945daca0) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/tls/libodbc.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 stat("/usr/local/unixODBC/lib/tls", 0x7fff945daca0) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/haswell/x86_64/libodbc.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 stat("/usr/local/unixODBC/lib/haswell/x86_64", 0x7fff945daca0) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/haswell/libodbc.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 stat("/usr/local/unixODBC/lib/haswell", 0x7fff945daca0) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/x86_64/libodbc.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 stat("/usr/local/unixODBC/lib/x86_64", 0x7fff945daca0) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/libodbc.so.2", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20~\0\0\0\0\0\0"..., 832) = 832
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0755, st_size=2866944, ...}) = 0
30716 19:05:06 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5fe9046000
30716 19:05:06 mmap(NULL, 497400, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5fe8fcc000
30716 19:05:06 mprotect(0x7f5fe8fd3000, 421888, PROT_NONE) = 0
30716 19:05:06 mmap(0x7f5fe8fd3000, 335872, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f5fe8fd3000
30716 19:05:06 mmap(0x7f5fe9025000, 81920, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x59000) = 0x7f5fe9025000
30716 19:05:06 mmap(0x7f5fe903a000, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0x7f5fe903a000
30716 19:05:06 mmap(0x7f5fe9042000, 14072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f5fe9042000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=26923, ...}) = 0
30716 19:05:06 mmap(NULL, 26923, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8fc5000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220\201\0\0\0\0\0\0"..., 832) = 832
30716 19:05:06 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\345Ga\367\265T\320\374\301V)Yf]\223\337"..., 68, 824) = 68
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0755, st_size=157224, ...}) = 0
30716 19:05:06 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\345Ga\367\265T\320\374\301V)Yf]\223\337"..., 68, 824) = 68
30716 19:05:06 mmap(NULL, 140408, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5fe8fa2000
30716 19:05:06 mmap(0x7f5fe8fa9000, 69632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f5fe8fa9000
30716 19:05:06 mmap(0x7f5fe8fba000, 20480, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18000) = 0x7f5fe8fba000
30716 19:05:06 mmap(0x7f5fe8fbf000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c000) = 0x7f5fe8fbf000
30716 19:05:06 mmap(0x7f5fe8fc1000, 13432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f5fe8fc1000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360q\2\0\0\0\0\0"..., 832) = 832
30716 19:05:06 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
30716 19:05:06 pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32
30716 19:05:06 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\t\233\222%\274\260\320\31\331\326\10\204\276X>\263"..., 68, 880) = 68
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0755, st_size=2029224, ...}) = 0
30716 19:05:06 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
30716 19:05:06 pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32
30716 19:05:06 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\t\233\222%\274\260\320\31\331\326\10\204\276X>\263"..., 68, 880) = 68
30716 19:05:06 mmap(NULL, 2036952, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5fe8db0000
30716 19:05:06 mprotect(0x7f5fe8dd5000, 1847296, PROT_NONE) = 0
30716 19:05:06 mmap(0x7f5fe8dd5000, 1540096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7f5fe8dd5000
30716 19:05:06 mmap(0x7f5fe8f4d000, 303104, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19d000) = 0x7f5fe8f4d000
30716 19:05:06 mmap(0x7f5fe8f98000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f5fe8f98000
30716 19:05:06 mmap(0x7f5fe8f9e000, 13528, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f5fe8f9e000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \22\0\0\0\0\0\0"..., 832) = 832
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=18816, ...}) = 0
30716 19:05:06 mmap(NULL, 20752, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5fe8daa000
30716 19:05:06 mmap(0x7f5fe8dab000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7f5fe8dab000
30716 19:05:06 mmap(0x7f5fe8dad000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f5fe8dad000
30716 19:05:06 mmap(0x7f5fe8dae000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f5fe8dae000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5fe8da8000
30716 19:05:06 arch_prctl(ARCH_SET_FS, 0x7f5fe8da8b80) = 0
30716 19:05:06 mprotect(0x7f5fe8f98000, 12288, PROT_READ) = 0
30716 19:05:06 mprotect(0x7f5fe8dae000, 4096, PROT_READ) = 0
30716 19:05:06 mprotect(0x7f5fe8fbf000, 4096, PROT_READ) = 0
30716 19:05:06 mprotect(0x7f5fe903a000, 4096, PROT_READ) = 0
30716 19:05:06 mprotect(0x606000, 4096, PROT_READ) = 0
30716 19:05:06 mprotect(0x7f5fe9075000, 4096, PROT_READ) = 0
30716 19:05:06 munmap(0x7f5fe8fc5000, 26923) = 0
30716 19:05:06 set_tid_address(0x7f5fe8da8e50) = 30716
30716 19:05:06 set_robust_list(0x7f5fe8da8e60, 24) = 0
30716 19:05:06 rt_sigaction(SIGRTMIN, {sa_handler=0x7f5fe8fa9bf0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f5fe8fb73c0}, NULL, 8) = 0
30716 19:05:06 rt_sigaction(SIGRT_1, {sa_handler=0x7f5fe8fa9c90, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f5fe8fb73c0}, NULL, 8) = 0
30716 19:05:06 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
30716 19:05:06 prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
30716 19:05:06 brk(NULL)                = 0x13a3000
30716 19:05:06 brk(0x13c4000)           = 0x13c4000
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=3035952, ...}) = 0
30716 19:05:06 mmap(NULL, 3035952, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8ac2000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=2996, ...}) = 0
30716 19:05:06 read(3, "# Locale name alias data base.\n#"..., 4096) = 2996
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_IDENTIFICATION", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=252, ...}) = 0
30716 19:05:06 mmap(NULL, 252, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe9074000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=27002, ...}) = 0
30716 19:05:06 mmap(NULL, 27002, PROT_READ, MAP_SHARED, 3, 0) = 0x7f5fe8fc5000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 futex(0x7f5fe8f9d634, FUTEX_WAKE_PRIVATE, 2147483647) = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_MEASUREMENT", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
30716 19:05:06 mmap(NULL, 23, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8ac1000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_TELEPHONE", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=47, ...}) = 0
30716 19:05:06 mmap(NULL, 47, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8ac0000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_ADDRESS", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=131, ...}) = 0
30716 19:05:06 mmap(NULL, 131, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8abf000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_NAME", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=62, ...}) = 0
30716 19:05:06 mmap(NULL, 62, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8abe000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_PAPER", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=34, ...}) = 0
30716 19:05:06 mmap(NULL, 34, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8abd000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_MESSAGES", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_MESSAGES/SYS_LC_MESSAGES", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=48, ...}) = 0
30716 19:05:06 mmap(NULL, 48, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8abc000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_MONETARY", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=270, ...}) = 0
30716 19:05:06 mmap(NULL, 270, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8abb000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_COLLATE", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=1518110, ...}) = 0
30716 19:05:06 mmap(NULL, 1518110, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8948000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_TIME", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=3360, ...}) = 0
30716 19:05:06 mmap(NULL, 3360, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8947000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_NUMERIC", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=50, ...}) = 0
30716 19:05:06 mmap(NULL, 50, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8946000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_CTYPE", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=201272, ...}) = 0
30716 19:05:06 mmap(NULL, 201272, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8914000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/gconv/UTF-16.so", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \21\0\0\0\0\0\0"..., 832) = 832
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=18688, ...}) = 0
30716 19:05:06 mmap(NULL, 20576, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5fe890e000
30716 19:05:06 mmap(0x7f5fe890f000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7f5fe890f000
30716 19:05:06 mmap(0x7f5fe8911000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f5fe8911000
30716 19:05:06 mmap(0x7f5fe8912000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f5fe8912000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 mprotect(0x7f5fe8912000, 4096, PROT_READ) = 0
30716 19:05:06 getuid()                 = 0
30716 19:05:06 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
30716 19:05:06 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
30716 19:05:06 close(3)                 = 0
30716 19:05:06 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
30716 19:05:06 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=510, ...}) = 0
30716 19:05:06 read(3, "# /etc/nsswitch.conf\n#\n# Example"..., 4096) = 510
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/libnss_files.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=26923, ...}) = 0
30716 19:05:06 mmap(NULL, 26923, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5fe8907000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_files.so.2", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3005\0\0\0\0\0\0"..., 832) = 832
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=51832, ...}) = 0
30716 19:05:06 mmap(NULL, 79672, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5fe88f3000
30716 19:05:06 mmap(0x7f5fe88f6000, 28672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f5fe88f6000
30716 19:05:06 mmap(0x7f5fe88fd000, 8192, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xa000) = 0x7f5fe88fd000
30716 19:05:06 mmap(0x7f5fe88ff000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xb000) = 0x7f5fe88ff000
30716 19:05:06 mmap(0x7f5fe8901000, 22328, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f5fe8901000
30716 19:05:06 close(3)                 = 0
30716 19:05:06 mprotect(0x7f5fe88ff000, 4096, PROT_READ) = 0
30716 19:05:06 munmap(0x7f5fe8907000, 26923) = 0
30716 19:05:06 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 lseek(3, 0, SEEK_CUR)    = 0
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=1910, ...}) = 0
30716 19:05:06 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1910
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
30716 19:05:06 lseek(3, 0, SEEK_END)    = 115
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=115, ...}) = 0
30716 19:05:06 read(3, "[MSSQLServer]\nDriver= ODBC Drive"..., 4096) = 115
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 getuid()                 = 0
30716 19:05:06 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 lseek(3, 0, SEEK_CUR)    = 0
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=1910, ...}) = 0
30716 19:05:06 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1910
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
30716 19:05:06 lseek(3, 0, SEEK_END)    = 115
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=115, ...}) = 0
30716 19:05:06 read(3, "[MSSQLServer]\nDriver= ODBC Drive"..., 4096) = 115
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 getuid()                 = 0
30716 19:05:06 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 lseek(3, 0, SEEK_CUR)    = 0
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=1910, ...}) = 0
30716 19:05:06 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1910
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
30716 19:05:06 lseek(3, 0, SEEK_END)    = 115
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=115, ...}) = 0
30716 19:05:06 read(3, "[MSSQLServer]\nDriver= ODBC Drive"..., 4096) = 115
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 getuid()                 = 0
30716 19:05:06 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 lseek(3, 0, SEEK_CUR)    = 0
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=1910, ...}) = 0
30716 19:05:06 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1910
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
30716 19:05:06 lseek(3, 0, SEEK_END)    = 115
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbc.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=115, ...}) = 0
30716 19:05:06 read(3, "[MSSQLServer]\nDriver= ODBC Drive"..., 4096) = 115
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/etc/odbcinst.ini", O_RDONLY) = 3
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
30716 19:05:06 read(3, "[ODBC Driver 17 for SQL Server]\n"..., 4096) = 120
30716 19:05:06 read(3, "", 4096)        = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/root/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 futex(0x7f5fe8daf0c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/local/unixODBC/lib/libodbc.so", O_RDONLY|O_CLOEXEC) = 3
30716 19:05:06 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20~\0\0\0\0\0\0"..., 832) = 832
30716 19:05:06 fstat(3, {st_mode=S_IFREG|0755, st_size=2866944, ...}) = 0
30716 19:05:06 close(3)                 = 0
30716 19:05:06 openat(AT_FDCWD, "/usr/share/locale/C.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/share/locale/C.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/share/locale/C/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/share/locale-langpack/C.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/share/locale-langpack/C.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 openat(AT_FDCWD, "/usr/share/locale-langpack/C/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
30716 19:05:06 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0x88, 0x1), ...}) = 0
30716 19:05:06 write(1, "[IM004][unixODBC][Driver Manager"..., 83) = 83
30716 19:05:06 write(2, "[ISQL]ERROR: Could not SQLConnec"..., 34) = 34
30716 19:05:06 exit_group(1)            = ?
30716 19:05:06 +++ exited with 1 +++

[sm-shaw]

Moving to discussion topic as not a HammerDB issue, (instead a unixODBC handle validation issue) and compiling and installing unixODBC from source.

[clain23]

We have successfully run the benchmark on properly compiled unixODBC and got the same results.

Also we have found that this issue was fixed in debian in 2017 https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=819622#22 so that's why we can't see performance difference.

Any other ideas?

[sm-shaw]

Hi, When you say "got the same results" is this the same results meaning the same performance on Linux and Windows - so the fix worked - or the same performance as the original post - so it didn't work?

Also, for clarity, this is a client fix, so the same performance means a HammerDB client on Linux and a HammerDB client on Windows running against a SQL Server on Windows will get the same performance.

It does not mean that on the server side, SQL Server on Linux and SQL Server on Windows are expected to have the same performance.

[clain23]

Sorry, I've meant the same poor performance 10 times slower than windows client. The sql server itself is on windows, the same one in both tests.

[sm-shaw]

This sounds like a different issue, --enable-fastvalidate has been tested and shown to improve performance by 2X bringing the Linux client performance to the same level as the Windows one. It is important to note that the HammerDB code is identical on both Windows and Linux, the only difference is at the 3rd party client level, so the issue here will either be in unixODBC or elsewhere on the system such as networking. At the moment, there is no evidence of there being anything that can be resolved at the HammerDB side.

[greenhal]

Have you run linix perf against it (https://www.brendangregg.com/perf.html)?
And are you using key/thinking time?

[sm-shaw]

A delayed reply as I have been focused on approving pull requests.

As an initial investigation, I have tried some tests with 5000 connections in the time permitting using PostgreSQL.
The script I have used is as follows:

dbset db pg
print dict
diset tpcc pg_superuser postgres
diset tpcc pg_defaultdbase postgres
diset tpcc pg_driver timed
diset tpcc pg_async_scale true
diset tpcc pg_async_client 10
diset tpcc pg_async_delay 100
diset tpcc pg_async_verbose false
diset tpcc pg_keyandthink true
diset tpcc pg_rampup 5
diset tpcc pg_duration 10
diset tpcc pg_timeprofile false
loadscript
vuset vu 500
vucreate
vurun
runtimer 1000
vudestroy

This creates 5000 connections as expected.

# ps -ef | grep post | grep tpcc | wc -l
5001

Checking lsof the open files are the database files.

postgres 422318 steve  109u      REG              259,1   1073741824 7089423424 /data/steve/opt/postgresql-14.1/data/base/17509/17553
postgres 422318 steve  110u      REG              259,1   1073741824 7089424133 /data/steve/opt/postgresql-14.1/data/base/17509/17553.1
postgres 422318 steve  111u      REG              259,1   1073741824 7089424141 /data/steve/opt/postgresql-14.1/data/base/17509/17553.2
postgres 422318 steve  112u      REG              259,1   1073741824 7089424146 /data/steve/opt/postgresql-14.1/data/base/17509/17553.3
postgres 422318 steve  113u      REG              259,1   1073741824 7089424152 /data/steve/opt/postgresql-14.1/data/base/17509/17553.4
postgres 422318 steve  114u      REG              259,1       557056 7089423465 /data/steve/opt/postgresql-14.1/data/base/17509/17510_vm
postgres 422318 steve  115u      REG              259,1      4521984 7089423460 /data/steve/opt/postgresql-14.1/data/base/17509/17510_fsm
postgres 422318 steve  116u      REG              259,1       622592 7089423461 /data/steve/opt/postgresql-14.1/data/base/17509/17522_fsm
postgres 422318 steve  117u      REG              259,1   1073741824 7089424157 /data/steve/opt/postgresql-14.1/data/base/17509/17553.5
postgres 422318 steve  118u      REG              259,1   1073741824 7089424162 /data/steve/opt/postgresql-14.1/data/base/17509/17553.6
postgres 422318 steve  119u      REG              259,1   1073741824 7089424168 /data/steve/opt/postgresql-14.1/data/base/17509/17553.7

and I got the result as follows:

Vuser 1:Test complete, Taking end Transaction Count.
Vuser 1:500 VU * 10 AC = 5000 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 6315 NOPM from 14415 PostgreSQL TPM

There were no issues in running this so far with 5000 sessions, and it did not show thread issues. I will re-run with 10000 to see if there are any issues between 5000 and 10000.

However, it is worth noting:

1. When using asynchronous clients with keyandthink then you would not typically connect all of those clients directly to the database, instead you would use middleware, in the case of PostgreSQL for example you would be expected to configure PgBouncer https://www.pgbouncer.org/
2. The Virtual Users themselves are OS threads, the asynchronous clients are connections by these threads using co-routines. If each session with keyandthink is doing 1 NOPM minute then you can use this as a sizing guide based on the throughput of one Virtual Users for a non-asynchronous test. As threads take more system resources than the connections then rather than 500 threads with 10 connections each it would use less system resources to configure 50 threads with 100 connections each.

[sm-shaw]

I have retested with the configuration as above, increasing the Virtual Users to 1000 with 10 Asynchronous Clients each.
Security limits are set as follows:

root@ubuntu:~# cat /etc/security/limits.conf
...
* hard nofile 100000
* soft nofile 100000
session required pam_limits.so

Using 10 minutes rampup and 30 minute test, the Virtual Users connect as expected:

Vuser 1000:Started asynchronous clients:vuser1000:ac1 vuser1000:ac2 vuser1000:ac3 vuser1000:ac4 vuser1000:ac5 vuser1000:ac6 vuser1000:ac7 vuser1000:ac8 vuser1000:ac9 vuser1000:ac10
...
Vuser 1001:Started asynchronous clients:vuser1001:ac1 vuser1001:ac2 vuser1001:ac3 vuser1001:ac4 vuser1001:ac5 vuser1001:ac6 vuser1001:ac7 vuser1001:ac8 vuser1001:ac9 vuser1001:ac10

After the 30 minute test I get the following result, which is correctly in the approx 1 NOPM per connection range (or 0.9-1.286 to be more precise - with the result 1.26 below)

Vuser 1:Test complete, Taking end Transaction Count.
Vuser 1:1000 VU * 10 AC = 10000 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 12600 NOPM from 28980 PostgreSQL TPM

We get 10,000 connections to the database.

postgres=# select count(*) from pg_stat_activity;
 count
-------
 10007
(1 row)

root@ubuntu:~# ps -ef | grep post | grep tpcc | wc -l
10001

CPU Activity is relatively low as expected as we are doing less throughput than a single virtual user without keying and thinking time.

12:49:58 AM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
12:50:01 AM  all    0.69    0.00    0.24    0.01    0.00    0.08    0.00    0.00    0.00   98.98
12:50:04 AM  all    0.62    0.00    0.21    0.01    0.00    0.08    0.00    0.00    0.00   99.07
12:50:07 AM  all    0.59    0.00    0.18    0.01    0.00    0.07    0.00    0.00    0.00   99.14
12:50:10 AM  all    0.60    0.00    0.25    0.01    0.00    0.12    0.00    0.00    0.00   99.04

and perf top also shows a relatively idle system:

   3.97%  [kernel]            [k] filemap_map_pages
   3.12%  postgres            [.] ComputeXidHorizons
   2.85%  [unknown]           [.] 0000000000000000
   2.80%  postgres            [.] hash_search_with_hash_value
   2.32%  postgres            [.] _bt_compare
   2.03%  perf                [.] __symbols__insert
   1.78%  libtcl8.6.so        [.] TEBCresume
   1.64%  libtcl8.6.so        [.] CreateHashEntry
   1.18%  postgres            [.] AllocSetAlloc
   0.87%  [kernel]            [k] xas_load
   0.86%  postgres            [.] SearchCatCache1
   0.83%  postgres            [.] PinBuffer
   0.77%  perf                [.] rb_next
   0.72%  postgres            [.] _bt_checkpage
   0.68%  [kernel]            [k] _raw_spin_lock
   0.67%  libtcl8.6.so        [.] Tcl_GetCommandFromObj
   0.66%  libc-2.31.so        [.] __strcoll_l
   0.63%  [kernel]            [k] copy_user_enhanced_fast_string
   0.62%  [kernel]            [k] native_irq_return_iret
   0.59%  libtcl8.6.so        [.] TclpAlloc
   0.53%  postgres            [.] GetSnapshotData

There is no stress on the OS or PostgreSQL running at this configuration. In particular, HammerDB or Tcl has no issues running this number of threads. Nevertheless, the advice stands that if testing large connection configurations, then middleware should be used.

In conclusion, it has not been possible to replicate the findings above and the 10,000 connection test ran as expected on Linux. It is possible that you have an issue with your configuration at the OS, network, database configuration layer preventing running a large connection count.

[alfer-aws]

Hi Steve,

I re-run the test increasing limits and i got the same results but after i disabled ASYNC_VERBOSE i finally got all the connections to the database as expected.

Vuser 1:Test complete: view report from SNAPID 55 to 56
Vuser 1:1000 VU * 10 AC = 10000 Active Sessions configured
Vuser 1:TEST RESULT : System achieved 12698 NOPM from 26428 Oracle TPM
Vuser 1:FINISHED SUCCESS
Vuser 1001:All asynchronous clients complete

Thinking about how the tcl script works and writes the log it actually makes sense as that would generate contention between threads trying to write at the same time.

If you have some time you could try with that parameter enabled and double check if you could replicate it.

Thank you for your time investigating into this, much appreciated

[sm-shaw]

OK - that makes a lot of sense and perhaps assumption/documentation on my part.

So ASYNC_VERBOSE is more to write output and diagnose and understand the workload as a test phase, rather than being intended for running with a large thread count. This is in a similar way to the test and timed script options - the test script is for running with a smaller virtual user count, for the timed script the output is suppressed. For the timed script as you would expect, output is much higher.

In both scenarios, the key aspect here is that no Virtual User (ie thread) writes output directly - every message is passed back to the main/master thread for writing. The key motivation here is that from the original design GUI displays should only be updated by one thread per application - so HammerDB was designed with this asynchronous message passing approach and in the GUI the Virtual Users grid is only every written to by the main GUI thread. The CLI is a thin-layer over the GUI so the underlying code is the same and the Virtual Users pass all output to the main thread. If logging is enabled this is an option in the main thread to write to the logfile as well. However the key contention is the large number of threads all sending messages to the main thread, and this explains why ThreadSend is top followed by ThreadQueue (in the main thread) as it is reading and processing all of the messages sent by the Virtual Users.

All tests for which you are measuring performance should have output suppressed, in this case all of the threads are entirely independent and therefore all run at the same time (this is in contrast to Python or Lua that has a GIL allowing only one thread to run at any one time as explained here https://www.hammerdb.com/blog/uncategorized/what-programming-languages-does-hammerdb-use-and-why-does-it-matter/) - however the output option is there for the 'test the test' phase to help diagnose the behaviour of the workload and ensure everything is set-up correctly before it is tested.

So perhaps a documentation fix is more appropriate to make it clear on exactly how output is received from the virtual users and written by the main thread to make it clear that large amounts of output are expected to be a bottleneck as they are all going to the main thread for processing.

[alfer-aws]

Typically i run tests with output suppressed as you are recommending but at the moment i am still in the discovery phase varying thinking time so i needed to double check before going "live".

I'm glad we figured it out, thanks again for your support

Alessandro