Using strace as a DG40DBC debugging tool

Recently, a customer who was using our SQL Server ODBC driver to connect Oracle to SQL Server, experienced an issue that proved difficult to get to the bottom of.

The customer was getting an ODBC Driver Manager log whenever DG4ODBC was used, with a resultant drag on performance — logging ODBC calls has a performance cost. The customer had checked the odbcinst.ini file for entries that enable logging; these entries were not present.

To help resolve this issue, we used the strace tool to discover what was going on "behind the scenes" when DG4ODBC was in use.

Because DG4ODBC is a library rather than an application, we had to attach strace to the Oracle listener process (DG4ODBC's "parent" application) to trace the operations associated with DG4ODBC.

The trace file showed which copy of odbcinst.ini was enabling logging.

These are the steps we took to attach strace to the Oracle listener:

$ ps -aef | grep tns*
oracle   16242     1  0 15:02 ?        00:00:00 /u01/app/oracle/product/11.2.0/xe/bin/tnslsnr LISTENER -inherit

$ sudo strace -p 16242 -f -o /tmp/mytracefile

(In a separate terminal window):

$ ./sqlplus / as sysdba

$ select * from mytable@mylink;

What Oracle has done "under the hood" is now captured in /tmp/mytracefile. We then used CTRL-C to stop strace and searched for sql.log (the ODBC Driver Manager log file) in /tmp/mytracefile. In our case, this showed:

16436 open("/etc/odbcinst.ini", O_RDONLY) = 7
16436 fstat(7, {st_mode=S_IFREG|0644, st_size=1365, ...}) = 0
16436 read(7, "[ODBC]\nTrace=Yes\nTraceFile=/tmp/"..., 4096) = 1365
16436 read(7, "", 4096)                 = 0
16436 close(7)                          = 0
16436 open("/u01/app/oracle/.odbcinst.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
16436 open("/tmp/sql.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 7