fetch column metadata error
Experiencing the intermittent ibm_db error, as detailed below.
An unexpected error occurred during data retrieval: An unexpected error occurred during data retrieval: uncaught throw :"Fetch Failure: <error message could not be retrieved>"
What's interesting is it will fail at different spots on the page when rapid refreshing (to reproduce the error). For example, in the below code it will sometimes fail on users.each
and other times on u.name
.
<% users.each do |u| %>
<%= u.name %>
The LUW (Linux/Unix/Windows) version of ibm_db also has this issue.
Working to reproduce issue with PASE CLI tool (thanks Tony Cairns).
Example of running
paseclitrace.ini:
; device_type=[tty,file]
; 0 - console
; 1 - file (/tmp/libdb400_trace)
; device_pid (device_type=1-file)
; 0 - /tmp/libdb400_trace
; 1 - /tmp/libdb400_trace[_pid]
; trace_type
; 0 - trace all
; 1 - trace errors only
; trace_stack
; 0 - no PASE stack dump
; 1 - PASE stack dump errors only
; 2 - PASE stack dump all
; trace_break (use with trace_stack)
; 0 - PASE dspjob stack (faster, less accurate)
; 1 - PASE dbx attach stack (much slower, more accurate)
; cli api=[0,1]
; 0 - API ignore
; 1 - API trace
device_type=1
device_pid=1
trace_type=1
trace_stack=1
trace_break=1
sqloverrideccsid400=1
sqlallocenv=1
sqlallocconnect=1
sqlallochandle=1
sqlallocstmt=1
sqlbindcol=1
sqlbindfiletocol=1
sqlbindfiletoparam=1
sqlbindparam=1
sqlbindparameter=1
sqlcancel=1
sqlclosecursor=1
sqlcolattributes=1
sqlcolumnprivileges=1
sqlcolumns=1
sqlconnect=1
sqlcopydesc=1
sqldatasources=1
sqldescribecol=1
sqldescribeparam=1
sqldisconnect=1
sqldriverconnect=1
sqlendtran=1
sqlerror=1
sqlexecdirect=1
sqlexecute=1
sqlextendedfetch=1
sqlfetch=1
sqlfetchscroll=1
sqlforeignkeys=1
sqlfreeconnect=0
sqlfreeenv=0
sqlfreehandle=0
sqlfreestmt=0
sqlgetcol=1
sqlgetconnectattr=1
sqlgetconnectoption=1
sqlgetcursorname=1
sqlgetdata=1
sqlgetdescfield=1
sqlgetdescrec=1
sqlgetdiagfield=1
sqlgetdiagrec=1
sqlgetenvattr=1
sqlgetfunctions=1
sqlgetinfo=1
sqlgetlength=1
sqlgetposition=1
sqlgetstmtattr=1
sqlgetstmtoption=1
sqlgetsubstring=1
sqlgettypeinfo=1
sqllanguages=1
sqlmoreresults=1
sqlnativesql=1
sqlnextresult=1
sqlnumparams=1
sqlnumresultcols=1
sqlparamdata=1
sqlparamoptions=1
sqlprepare=1
sqlprimarykeys=1
sqlprocedurecolumns=1
sqlprocedures=1
sqlputdata=1
sqlreleaseenv=1
sqlrowcount=1
sqlsetconnectattr=1
sqlsetconnectoption=1
sqlsetcursorname=1
sqlsetdescfield=1
sqlsetdescrec=1
sqlsetenvattr=1
sqlsetparam=1
sqlsetstmtattr=1
sqlsetstmtoption=1
sqlspecialcolumns=1
sqlstarttran=1
sqlstatistics=1
sqltableprivileges=1
sqltables=1
sqltransact=1
##Recreate error##
$ cd git/ibmdb_fetchbug
$ export LIBPATH=/QOpenSys/download/trace-1.0.2-xlc
$ export PASETRACE=/QOpenSys/download/trace-1.0.2-xlc/paseclitrace.ini
$ export IBM_DB_GIL="00000000000000000000000000000000000000000000"
$ rails s -p50000
/PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/railties-4.1.8/lib/rails/app_rails_loader.rb:37: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
/PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:222: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
=> Booting Puma
=> Rails 4.1.8 application starting in development on http://0.0.0.0:50000
=> Run `rails server -h` for more startup options
=> Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
=> Ctrl-C to shutdown server
Puma 2.11.1 starting...
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:50000
<--- here is where I go to the browser and invoke a URL in the app --->
Started GET "/users/2" for 216.114.244.204 at 2015-07-07 17:38:17 +0000
(7.6ms) SET SCHEMA ab1_d
(8.1ms) SET SCHEMA ab1_d
ActiveRecord::SchemaMigration Load (5.3ms) SELECT schema_migrations.* FROM schema_migrations
Processing by UsersController#show as HTML
Parameters: {"id"=>"2"} <--- it hangs here.
WRKACTJOB STS is THDW with the following as the last entry in the call stack:
libpthread.a(shr_xpg5 > 00000584 _event_sleep
Call stack with panic
. This revealed we needed to get dbx working with 64-bit PASE.
Display Call Stack
System: xxxxx
Job: QP0ZSPWP User: QSECOFR Number: 297055
Thread: 00000009
Type Program Statement Procedure
QP0ZPCP2 QSYS _CXX_PEP__Fv
QP0ZPCPN QSYS 264 Qp0zNewProcess
QP2FORK QSYS _CXX_PEP__Fv
QP2FORK QSYS 16 main
QP2USER2 QSYS 10 __Qp2Fork
QP2USER2 QSYS 6 runpase_main__FPi
QP2USER2 QSYS 5 runpase_common__FiPvT2
P dbx 00000074 __start
P dbx 000001C8 main
P libdbx.a(shr_64.o) 0000058C dpi_main
P libdbx.a(shr_64.o) 000001CC dpi_command
P libdbx.a(shr_64.o) 000000F4 process_input
P libdbx.a(shr_64.o) 00000844 yyparse
P libdbx.a(shr_64.o) 00000C20 topeval
P libdbx.a(shr_64.o) 0000472C eval
P libdbx.a(shr_64.o) 00000034 wherecmd
P libdbx.a(shr_64.o) 00000294 walkstack
P libdbx.a(shr_64.o) 000000C0 touch_sym
P libdbx.a(shr_64.o) 000002CC touch_file
P libdbx.a(shr_64.o) 000009E0 readsyms
P libdbx.a(shr_64.o) 00000F20 enter_nl
P libdbx.a(shr_64.o) 0000081C entersym
P libdbx.a(shr_64.o) 00000488 typeName
P libdbx.a(shr_64.o) 00000394 constype
P libdbx.a(shr_64.o) 00000E08 constype
P libdbx.a(shr_64.o) 0000019C consRecord
P libdbx.a(shr_64.o) 00000394 constype
P libdbx.a(shr_64.o) 00000E50 constype
P libdbx.a(shr_64.o) 00000394 constype
P libdbx.a(shr_64.o) 00001470 constype
P libdbx.a(shr_64.o) 000000C8 panic <---- YIKES
P libdbx.a(shr_64.o) 00000068 errmsg
P libc.a(shr_64.o) 00000080 fflush
P libc.a(shr_64.o) 00000794 fflush_unlocked
P libc.a(shr_64.o) 000000BC _xflsbuf
P libc.a(shr_64.o) 00000080 _xwrite
P libc.a(shr_64.o) 00000260 write
P unix 00000008 <syscall64>:kwrite
Current status: Working with IBM to produce PTF for dbx
Comments (157)
-
Account Deleted -
reporter PTF SI57578 has been loaded(n1) and I am still getting the
panic
(n2). I've included my full PTF levels (WRKGRPPTF
)(n3).Let me know what next steps I can take.
(n1)
Display PTF Status System: xxxxxx Product ID . . . . . . . . . . . . . : 5770SS1 IPL source . . . . . . . . . . . . . : ##MACH#B Release of base option . . . . . . . : V7R2M0 L00 Type options, press Enter. 5=Display PTF details 6=Print cover letter 8=Display cover letter 10=Display PTF apply information PTF IPL Opt ID Status Action TC14276 Permanently applied None TC14101 Superseded None TA14276 Permanently applied None TA14101 Superseded None SI57578 Temporarily applied None SI57147 Permanently applied None SI57146 Permanently applied None More... F3=Exit F11=Display alternate view F17=Position to F12=Cancel
(n2)
Display Call Stack System: xxxxxx Job: QP0ZSPWP User: QSECOFR Number: 644963 Thread: 00000025 Type Program Statement Procedure QP0ZPCP2 QSYS _CXX_PEP__Fv QP0ZPCPN QSYS 264 Qp0zNewProcess QP2FORK QSYS _CXX_PEP__Fv QP2FORK QSYS 16 main QP2USER2 QSYS 10 __Qp2Fork QP2USER2 QSYS 6 runpase_main__FPi QP2USER2 QSYS 5 runpase_common__FiPvT2 P dbx 0000006C __start P dbx 000001CC main P libdbx.a(shr.o) 00000504 dpi_main P libdbx.a(shr.o) 000001DC dpi_command P libdbx.a(shr.o) 000000F4 process_input P libdbx.a(shr.o) 000007C8 yyparse P libdbx.a(shr.o) 00000C4C topeval P libdbx.a(shr.o) 000047E4 eval P libdbx.a(shr.o) 00000024 wherecmd P libdbx.a(shr.o) 0000027C walkstack P libdbx.a(shr.o) 000000A4 touch_sym P libdbx.a(shr.o) 00000260 touch_file P libdbx.a(shr.o) 00000B68 readsyms P libdbx.a(shr.o) 00000F70 enter_nl P libdbx.a(shr.o) 000007B8 entersym P libdbx.a(shr.o) 00000470 typeName P libdbx.a(shr.o) 00000364 constype P libdbx.a(shr.o) 00000D40 constype P libdbx.a(shr.o) 00000184 consRecord P libdbx.a(shr.o) 00000364 constype P libdbx.a(shr.o) 00000D88 constype P libdbx.a(shr.o) 00000364 constype P libdbx.a(shr.o) 000012BC constype P libdbx.a(shr.o) 000000C8 panic <---------------- P libdbx.a(shr.o) 00000040 errmsg P libc.a(shr.o) 00000080 fflush P libc.a(shr.o) 00000784 fflush_unlocked P libc.a(shr.o) 000000AC _xflsbuf P libc.a(shr.o) 00000070 _xwrite P libc.a(shr.o) 000001A4 write P unix 00000008 <syscall32>:kwrite
(n3)
PTF Group Level Status SF99776 1 Installed SF99775 5 Installed SF99769 1 Installed SF99767 1 Installed SF99766 3 Installed SF99759 3 Related group SF99747 10 Installed SF99721 3 Installed SF99720 14276 Installed SF99719 26 Installed SF99718 11 Installed SF99717 1 Installed SF99716 4 Installed SF99716 6 Installed SF99715 9 Installed SF99714 2 Installed SF99713 5 Installed SF99713 9 Installed SF99702 4 Installed SF99702 5 Installed SF99481 3 Installed SF99480 3 Installed
-
Account Deleted I dunno ... check PTF was good ... $ which dbx /QOpenSys/usr/bin/dbx $ dbx /QOpenSys/usr/bin/dbx Type 'help' for help. reading symbolic information ...warning: no source compiled with -g
HOME: No such file or directory (dbx) map
-
Account Deleted sorry format ...
$ which dbx /QOpenSys/usr/bin/dbx $ dbx /QOpenSys/usr/bin/dbx Type 'help' for help. reading symbolic information ...warning: no source compiled with -g HOME: No such file or directory (dbx) map ... paste this ...
-
reporter Here are the results:
$ export LIBPATH=/QOpenSys/download/trace-1.0.2-xlc $ export PASETRACE=/QOpenSys/download/trace-1.0.2-xlc/paseclitrace.ini $ export IBM_DB_GIL="00000000000000000000000000000000000000000000" $ which dbx /QOpenSys/usr/bin/dbx $ dbx /QOpenSys/usr/bin/dbx Type 'help' for help. reading symbolic information ...warning: no source compiled with -g (dbx) map Entry 1: Object name: /QOpenSys/usr/bin/dbx Text origin: 0x10000000 Text length: 0x103b5 Data origin: 0x30000589 Data length: 0x79f7 File descriptor: 0x3 Entry 2: Object name: /usr/lib/libC.a Member name: ansicore_32.o Text origin: 0xd037a600 Text length: 0x1c500 Data origin: 0x20560a00 Data length: 0x842c File descriptor: 0x4 Entry 3: Object name: /usr/lib/libC.a Member name: ansi_32.o Text origin: 0xd012ca00 Text length: 0x2287f7 Data origin: 0x20582000 Data length: 0x36690 File descriptor: 0x5 Entry 4: Object name: /usr/lib/libC.a Member name: shrcore.o Text origin: 0xd0357600 Text length: 0x22089 Data origin: 0x2055bc00 Data length: 0x3e58 File descriptor: 0x6 Entry 5: Object name: /usr/lib/libcdebug.a Member name: shr.o Text origin: 0xd1b10100 Text length: 0xc4ec Data origin: 0x20691b10 Data length: 0xff4 File descriptor: 0x7 Entry 6: Object name: /usr/lib/libdbx.a Member name: coredebug.o Text origin: 0xd1d94e80 Text length: 0x1addd Data origin: 0x2068ed28 Data length: 0x16d8 File descriptor: 0x8 Entry 7: Object name: /usr/lib/libpthdebug.a Member name: shr.o Text origin: 0xd1d1c100 Text length: 0x77216 Data origin: 0x205bf188 Data length: 0xce428 File descriptor: 0x9 Entry 8: Object name: /usr/lib/libdbx.a Member name: stackdebug.o Text origin: 0xd1af1ca0 Text length: 0x1df00 Data origin: 0x205bc790 Data length: 0x1d40 File descriptor: 0xa Entry 9: Object name: /usr/lib/libdbx.a Member name: procdebug.o Text origin: 0xd1ad4080 Text length: 0x1c185 Data origin: 0x205b9800 Data length: 0x1ff0 File descriptor: 0xb Entry 10: Object name: /usr/lib/libiconv.a Member name: shr4.o Text origin: 0xd04e3100 Text length: 0x26489 Data origin: 0x2056dd80 Data length: 0x13f2c File descriptor: 0xc Entry 11: Object name: /usr/lib/libC.a Member name: shr.o Text origin: 0xd010c100 Text length: 0x1fed6 Data origin: 0x20569d00 Data length: 0x30f0 File descriptor: 0xd Entry 12: Object name: /usr/lib/libdecNumber.a Member name: shr.o Text origin: 0xd12de100 Text length: 0x15b4e Data origin: 0x20558080 Data length: 0x2b68 File descriptor: 0xe Entry 13: Object name: /usr/lib/libpthreads.a Member name: shr_comm.o Text origin: 0x20434000 Text length: 0x315f Data origin: 0x20510000 Data length: 0x43920 File descriptor: 0xf Entry 14: Object name: /usr/lib/libcrypt.a Member name: shr.o Text origin: 0xd0356100 Text length: 0x9be Data origin: 0x2050f6a8 Data length: 0x120 File descriptor: 0x10 Entry 15: Object name: /usr/lib/libdbx.a Member name: shr.o Text origin: 0xd1b37100 Text length: 0x1e4a09 Data origin: 0x20693d00 Data length: 0x1cc170 File descriptor: 0x11 Entry 16: Object name: /usr/lib/libpthreads.a Member name: shr_xpg5.o Text origin: 0x203f4000 Text length: 0x3f14d Data origin: 0x20554000 Data length: 0x3f8c File descriptor: 0x12 Entry 17: Object name: /usr/lib/libc.a Member name: shr.o Text origin: 0x20000000 Text length: 0x3f3191 Data origin: 0x20438350 Data length: 0xd6810 File descriptor: 0x13
-
Account Deleted Well, looks correct (32-bit) ... but why dbx not work with whatever Ruby you are using???
bash-4.3$ which ruby /usr/bin/ruby bash-4.3$ dbx /usr/bin/ruby Type 'help' for help. reading symbolic information ...dbx: fatal error: nesting depth limit (25) exceeded. Use the -d option to increase nesting depth limit. bash-4.3$ dbx -d 100 /usr/bin/ruby Type 'help' for help. reading symbolic information ...internal error: assertion failed at line 5562 in file object.c ... errors ... (dbx) where __start() at 0x10000150 (dbx) map Entry 1: Object name: /usr/bin/ruby Text origin: 0x10000000
-
reporter Here are the results. Could you run
which ruby | xargs ls -all
so we can see which version you are pointing at? Mine is pointing atprV2R1
, as shown below.$ which ruby | xargs ls -all lrwxrwxrwx 1 aaron 0 68 May 22 21:18 /QOpenSys/usr/bin/ruby -> ../../../PowerRuby/prV2R1/bin/ruby $ dbx /QOpenSys/usr/bin/ruby Type 'help' for help. reading symbolic information ...dbx: fatal error: nesting depth limit (25) exceeded. Use the -d option to increase nesting depth limit. $ dbx -d 100 /QOpenSys/usr/bin/ruby Type 'help' for help. reading symbolic information ...internal error: assertion failed at line 5562 in file object.c internal error: assertion failed at line 5562 in file object.c .... same error many times .... internal error: assertion failed at line 5562 in file object.c (dbx) where __start() at 0x10000150 (dbx) map Entry 1: Object name: /QOpenSys/usr/bin/ruby Text origin: 0x10000000 Text length: 0x33ebe9 Data origin: 0x20558adc Data length: 0x3e650 File descriptor: 0x3 Entry 2: Object name: /usr/lib/librtl.a Member name: shr.o Text origin: 0xd0564b80 Text length: 0x2f6 Data origin: 0xf010cd80 Data length: 0x7c File descriptor: 0x4 Entry 3: Object name: /usr/lib/libc.a Member name: shr.o Text origin: 0x20044000 Text length: 0x3f3191 Data origin: 0x20438350 Data length: 0xd6810 File descriptor: 0x5 Entry 4: Object name: /usr/lib/libcrypt.a Member name: shr.o Text origin: 0xd0356100 Text length: 0x9be Data origin: 0x2050f6a8 Data length: 0x120 File descriptor: 0x6 Entry 5: Object name: /usr/lib/libpthread.a Member name: shr_xpg5.o Text origin: 0x20004000 Text length: 0x3f14d Data origin: 0x20554000 Data length: 0x3f8c File descriptor: 0x7 Entry 6: Object name: /usr/lib/libpthread.a Member name: shr_comm.o Text origin: 0x20000000 Text length: 0x315f Data origin: 0x20510000 Data length: 0x43920 File descriptor: 0x8
-
Account Deleted Well, answer V2R0, but slightly irrelevant (truthfully). I much more interested in a strategy of debug where YOU (not me), can be self helping, aka, libdb400.a trace tool 'works for anybody'. So, while DB2 problem itself is nasty, it is also the perfect sort of issue to work out the tools (ie, 'what the blue blazing saddles is going on' --- perfect problem)
(dbx) quit bash-4.3$ which ruby | xargs ls -all lrwxrwxrwx 1 adc 0 52 Mar 31 12:18 /usr/bin/ruby -> /PowerRuby/prV2R0/bin/ruby b
-
Account Deleted So, next, i would like your to dbx attach to a running Ruby application ...
> ruby my_problem_app > ps > 12345 ruby > dbx -d 100 -a 12345 > where
-
reporter The resulting error was big enough that I put it into a Bitbucket snippet (click here).
-
Account Deleted Well belive it or not, that was ok ... but do it again, and, run where twice ...
> ruby my_problem_app > ps > 12345 ruby > dbx -d 100 -a 12345 dbx> where ** ton o errors *** dbx> where -- should look ok, paste here --
-
reporter Here is the second
where
...(dbx) where _event_sleep(??, ??, ??, ??, ??, ??) at 0x2001a4d4 _event_wait(??, ??) at 0x2001b1cc _cond_wait_local(??, ??, ??) at 0x20029130 _cond_wait(??, ??, ??) at 0x200298c4 pthread_cond_timedwait(??, ??, ??) at 0x2002a1cc unnamed block in native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c" unnamed block in native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c" unnamed block in native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c" native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c" sleep_timeval.constprop.52(th = 0x242e55b0, tv = (...)), line 1049 in "thread.c" rb_f_sleep(argc = 1, argv = 0x242e79a4), line 4230 in "process.c" call_cfunc_m1(func = ??, recv = ??, argc = ??, argv = ??), line 1317 in "vm_insnhelper.c" vm_call_cfunc_with_frame(th = 0x242e55b0, reg_cfp = 0x24367940, ci = ??), line 1489 in "vm_eval.c" unnamed block in vm_exec_core(th = ??, initial = ??), line 1073 in "vm_eval.c" unnamed block in vm_exec_core(th = ??, initial = ??), line 1073 in "vm_eval.c" vm_exec_core(th = ??, initial = ??), line 1073 in "vm_eval.c" unnamed block in vm_exec(th = 0x242e55b0), line 1398 in "vm_eval.c" vm_exec(th = 0x242e55b0), line 1398 in "vm_eval.c" unnamed block in invoke_block_from_c(th = 0x242e55b0, block = 0x24367a90, self = 605910520, argc = 0, argv = ??, blockptr = ??, cref = (nil), defined_class = ??), line 817 in "vm_eval.c" invoke_block_from_c(th = 0x242e55b0, block = 0x24367a90, self = 605910520, argc = 0, argv = ??, blockptr = ??, cref = (nil), defined_class = ??), line 817 in "vm_eval.c" unnamed block in vm_invoke_proc(th = 0x242e55b0, proc = 0x24367a90, self = 605910520, defined_class = 564888580, argc = 0, argv = 0x241d75c4, blockptr = (nil)), line 881 in "vm_eval.c" vm_invoke_proc(th = 0x242e55b0, proc = 0x24367a90, self = 605910520, defined_class = 564888580, argc = 0, argv = 0x241d75c4, blockptr = (nil)), line 881 in "vm_eval.c" unnamed block in thread_start_func_2(th = 0x242e55b0, stack_start = 0x243ea000), line 535 in "thread.c" thread_start_func_2(th = 0x242e55b0, stack_start = 0x243ea000), line 535 in "thread.c" thread_start_func_1(th_ptr = 0x242e55b0), line 803 in "thread_pthread.c"
-
Account Deleted Ok, i am greatly confused, dbx attach just worked fine. But when you try libdb400.a stack, it blows up???
Is this correct?
-
reporter Ok, I am going to lay out two scenarios in full. The first is using dbx "inline" (i.e. I don't manually invoke it in the shell and instead paseclitrace does.)
#Scenario 1
$ cd git/ibmdb_fetchbug/ $ export LIBPATH=/QOpenSys/download/trace-1.0.2-xlc $ export PASETRACE=/QOpenSys/download/trace-1.0.2-xlc/paseclitrace.ini $ export IBM_DB_GIL="00000000000000000000000000000000000000000000" $ rails s -p50000 => Booting Puma => Rails 4.1.8 application starting in development on http://0.0.0.0:50000 => Run `rails server -h` for more startup options => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option) => Ctrl-C to shutdown server Puma 2.11.1 starting... * Min threads: 0, max threads: 16 * Environment: development * Listening on tcp://0.0.0.0:50000
At this point I load a page in browser and it remains waiting for a response. Below are the call stacks for the dbx and ruby jobs. I waited for at least 15 minutes with no response. Note there isn't a
panic
in the dbx job like before. I am not sure whypanic
isn't there anymore. As best I can tell I did everything the same as this morning.dbx job (not initiated by manual attachment via pid):
Display Call Stack System: xxxx Job: QP0ZSPWP User: QSECOFR Number: 658889 Thread: 000003FE Type Program Statement Procedure QP0ZPCP2 QSYS _CXX_PEP__Fv QP0ZPCPN QSYS 264 Qp0zNewProcess QP2FORK QSYS _CXX_PEP__Fv QP2FORK QSYS 16 main QP2USER2 QSYS 10 __Qp2Fork QP2USER2 QSYS 6 runpase_main__FPi QP2USER2 QSYS 5 runpase_common__FiPvT2 P dbx 0000006C __start P dbx 000001CC main P libdbx.a(shr.o) 00000504 dpi_main P libdbx.a(shr.o) 000001DC dpi_command P libdbx.a(shr.o) 000000F4 process_input P libdbx.a(shr.o) 000007C8 yyparse P libdbx.a(shr.o) 00000C4C topeval P libdbx.a(shr.o) 000047E4 eval P libdbx.a(shr.o) 00000024 wherecmd P libdbx.a(shr.o) 0000028C walkstack P libdbx.a(shr.o) 000000B0 printfullcallinfo P libdbx.a(shr.o) 00000204 printcallinfo P libdbx.a(shr.o) 000001A4 printparams P libdbx.a(shr.o) 000002D4 printparamv P libdbx.a(shr.o) 0000069C printv P libdbx.a(shr.o) 00000310 printval P libdbx.a(shr.o) 000009C8 c_printval P libc.a(shr.o) 000000E4 fprintf P libc.a(shr.o) 00001E74 _doprnt P libc.a(shr.o) 000000B8 fwrite@AF5_4 P libc.a(shr.o) 00000184 fwrite_unlocked P libc.a(shr.o) 000000AC _xflsbuf P libc.a(shr.o) 00000070 _xwrite P libc.a(shr.o) 000001A4 write P unix 00000008 <syscall32>:kwrite
Ruby job with Rails server:
Display Call Stack System: xxxx Job: QP0ZSPWP User: QSECOFR Number: 658887 Thread: 000001DD Type Program Statement Procedure QP0ZPCP2 QSYS _CXX_PEP__Fv QP0ZPCPN QSYS 264 Qp0zNewProcess QP2FORK QSYS _CXX_PEP__Fv QP2FORK QSYS 16 main QP2USER2 QSYS 10 __Qp2Fork QP2USER2 QSYS 6 runpase_main__FPi QP2USER2 QSYS 5 runpase_common__FiPvT2 P ruby 0000006C __start P ruby 36 00000064 main P ruby 318 00000074 ruby_run_node P ruby 253 000000E4 ruby_exec_internal P ruby 00000148 rb_iseq_eval_main P ruby 000000AC vm_exec P ruby 000012F8 vm_exec_core P ruby 000001E0 vm_call_method P ruby 00000138 vm_call_cfunc_with_frame P ruby 00000030 call_cfunc_1 P ruby 1587 0000070C rb_require_safe P ruby 615 00000164 rb_load_internal0 P ruby 00000138 rb_iseq_eval P ruby 000000AC vm_exec P ruby 00001690 vm_exec_core P ruby 000001E0 vm_call_method P ruby 00000138 vm_call_cfunc_with_frame P ruby 0000002C call_cfunc_0 P ruby 00000018 rb_obj_tap P ruby 00000074 rb_yield P ruby 00000BC0 invoke_block_from_c P ruby 000000AC vm_exec P ruby 000012F8 vm_exec_core P ruby 000001E0 vm_call_method P ruby 00000138 vm_call_cfunc_with_frame P ruby 00000038 call_cfunc_m1 P ruby 00000120 thread_join_m P ruby 853 000000F0 rb_ensure P ruby 00000118 thread_join_sleep P ruby 000000D4 native_sleep.constprop.56 P libpthread.a(shr_xpg5 > 000001A0 pthread_cond_wait P libpthread.a(shr_xpg5 > 000000C8 _cond_wait P libpthread.a(shr_xpg5 > 000004FC _cond_wait_local P libpthread.a(shr_xpg5 > 00000350 _event_wait P+ P+ libpthread.a(shr_xpg5 > 00000584 _event_sleep P libpthread.a(shr_xpg5 > 00000584 _event_sleep
Convey libdb400* files from
/tmp/
viacat
:$ ls -all /tmp/ total 760 drwxrwsrwt 7 qsys 0 36864 Aug 18 21:48 . drwxrwsrwx 24 qsys 0 241664 Jun 5 16:59 .. drwxrwxrwt 5 aaron 0 8192 Aug 18 01:25 .com_ibm_tools_attach drwxrwsrwx 2 qsecofr 0 8192 Jun 5 14:17 ZendCoreMySql -rwxrwxrwx 1 qsecofr 0 770 Jun 5 14:16 ZendServerInstall.log drwxrwsrwx 2 qbrms 0 8192 May 21 22:52 brms -rw-r--r-- 1 aaron 0 19 Aug 18 21:31 libdb400_trace_cmd1_89956 -rw-r--r-- 1 aaron 0 432 Aug 18 21:31 libdb400_trace_cmd2_89956 -rwxrwxrwx 1 qsys 0 3372 May 21 22:52 lprcume.log -rwxrwxrwx 1 qsys 0 2843 May 21 22:37 lpume.log -rw-r--r-- 1 qsecofr 0 3 Aug 8 00:13 sshd.pid $ cat /tmp/libdb400_trace_cmd1_89956 thread detach quit $ cat /tmp/libdb400_trace_cmd2_89956 print "---------thread 1-----------" thread current 1 where print "---------thread 2-----------" thread current 2 where print "---------thread 3-----------" thread current 3 where print "---------thread 4-----------" thread current 4 where print "---------thread 5-----------" thread current 5 where print "---------thread 6-----------" thread current 6 where print "---------thread 7-----------" thread current 7 where detach quit
# Scenario 2 ##Shell session 1 Note I do not use the paseclitrace in this scenario. Should I be using it? Note I tried this scenario with paseclitrace but it didn't produce anything in
/tmp
.$ cd git/ibmdb_fetchbug/ $ rails s -p50000 => Booting Puma => Rails 4.1.8 application starting in development on http://0.0.0.0:50000 => Run `rails server -h` for more startup options => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option) => Ctrl-C to shutdown server Puma 2.11.1 starting... * Min threads: 0, max threads: 16 * Environment: development * Listening on tcp://0.0.0.0:50000
##Shell session 2
$ ps -U aaron UID PID TTY TIME CMD 111 76001 pts/1 0:00 bash 111 89984 pts/0 0:00 bash 111 89987 pts/2 0:00 bash 111 89992 pts/3 0:00 bash 111 89994 pts/0 0:02 ruby 111 89995 pts/2 0:00 ps $ dbx -d 100 -a 89994 Waiting to attach to process 89994 ... Successfully attached to /PowerRuby/prV2R1/bin/ruby. Type 'help' for help. reading symbolic information ...internal error: assertion failed at line 5562 in file object.c internal error: assertion failed at line 5562 in file object.c ... same error repeated ... internal error: assertion failed at line 5562 in file object.c stopped in _event_sleep at 0x2001a6e4 ($t7) 0x2001a6e4 (_event_sleep+0x584) 80410014 lwz r2,0x14(r1) (dbx)
dbx job (initiated manually as shown above):
Display Call Stack System: xxxx Job: QP0ZSPWP User: QSECOFR Number: 658926 Thread: 00000401 Type Program Statement Procedure QP0ZPCP2 QSYS _CXX_PEP__Fv QP0ZPCPN QSYS 264 Qp0zNewProcess QP2FORK QSYS _CXX_PEP__Fv QP2FORK QSYS 16 main QP2USER2 QSYS 10 __Qp2Fork QP2USER2 QSYS 6 runpase_main__FPi QP2USER2 QSYS 5 runpase_common__FiPvT2 P dbx 0000006C __start P dbx 000002A0 main P dbx 00000238 getline P dbx 000001E8 io_readbuff P libc.a(shr.o) 0000028C read P unix 00000008 <syscall32>:kread Bottom
Ruby job with Rails server:
Display Call Stack System: xxxx Job: QP0ZSPWP User: QSECOFR Number: 658921 Thread: 000001E4 Type Program Statement Procedure QP0ZPCP2 QSYS _CXX_PEP__Fv QP0ZPCPN QSYS 264 Qp0zNewProcess QP2FORK QSYS _CXX_PEP__Fv QP2FORK QSYS 16 main QP2USER2 QSYS 10 __Qp2Fork QP2USER2 QSYS 6 runpase_main__FPi QP2USER2 QSYS 5 runpase_common__FiPvT2 P ruby 0000006C __start P ruby 36 00000064 main P ruby 318 00000074 ruby_run_node P ruby 253 000000E4 ruby_exec_internal P ruby 00000148 rb_iseq_eval_main P ruby 000000AC vm_exec P ruby 000012F8 vm_exec_core P ruby 000001E0 vm_call_method P ruby 00000138 vm_call_cfunc_with_frame P ruby 00000030 call_cfunc_1 P ruby 1587 0000070C rb_require_safe P ruby 615 00000164 rb_load_internal0 P ruby 00000138 rb_iseq_eval P ruby 000000AC vm_exec P ruby 00001690 vm_exec_core P ruby 000001E0 vm_call_method P ruby 00000138 vm_call_cfunc_with_frame P ruby 0000002C call_cfunc_0 P ruby 00000018 rb_obj_tap P ruby 00000074 rb_yield P ruby 00000BC0 invoke_block_from_c P ruby 000000AC vm_exec P ruby 000012F8 vm_exec_core P ruby 000001E0 vm_call_method P ruby 00000138 vm_call_cfunc_with_frame P ruby 00000038 call_cfunc_m1 P ruby 00000120 thread_join_m P ruby 853 000000F0 rb_ensure P ruby 00000118 thread_join_sleep P ruby 000000D4 native_sleep.constprop.56 P libpthread.a(shr_xpg5 > 000001A0 pthread_cond_wait P libpthread.a(shr_xpg5 > 000000C8 _cond_wait P libpthread.a(shr_xpg5 > 000004FC _cond_wait_local P libpthread.a(shr_xpg5 > 00000350 _event_wait P libpthread.a(shr_xpg5 > 00000584 _event_sleep P unix 00000008 <syscall32>:thread_tsleep
In summary, the
panic
is gone but it is still hanging. -
Account Deleted Anyway, panic aside, dbx attach is slow, so thinking removing dbx and dumping stack from within libdb400.a trace module ... but not tonight ... I will think design over this evening.
-
Account Deleted It will look something like this ...
#include <pthread.h> #include <stdio.h> #include <stdlib.h> #include <unistd.h> #include <string.h> #define uint16 unsigned short #define uint32 unsigned int #define Address unsigned int typedef struct FN_NAME { uint16 nameLen; char name[1]; }; typedef struct tbtable_short { uint32 zeroAnchor; /* include this in to make things simpler */ uint32 version:8; /* traceback format version */ uint32 lang:8; /* See language values below */ uint32 globallink:1; /* Set if routine is global linkage */ uint32 is_eprol:1; /* Set if is out-of-line epilog/prologue */ uint32 has_tboff:1; /* Set if offset from start of proc stored */ uint32 int_proc:1; /* Set if routine is internal */ uint32 has_ctl:1; /* Set if routine involves controlled storage */ uint32 tocless:1; /* Set if routine contains no TOC */ uint32 fp_present:1; /* Set if routine performs FP operations */ uint32 log_abort:1; /* Set if routine logs or aborts FP ops */ uint32 int_hndl:1; /* Set if routine is interrupt handler */ uint32 name_present:1; /* Set if name is present in proc table */ uint32 uses_alloca:1; /* Set if alloca used to allocate storage */ uint32 cl_dis_inv:3; /* On-condition directives, see below */ uint32 saves_cr:1; /* Set if procedure saves the condition reg */ uint32 saves_lr:1; /* Set if procedure saves the link reg */ uint32 stores_bc:1; /* Set if procedure stores the backchain */ uint32 fixup:1; /* Set if code is generated fixup code. */ uint32 fpr_saved:6; /* Number of FPRs saved, max of 32 */ uint32 spare3:2; /* Spare bits */ uint32 gpr_saved:6; /* Number of GPRs saved, max of 32 */ uint32 fixedparms:8; /* Number of fixed point parameters */ uint32 floatparms:7; /* Number of floating point parameters */ uint32 parmsonstk:1; /* Set if all parameters placed on stack */ }; typedef struct TiaStackFrame32 { uint32 backChain; uint32 savedCR; uint32 savedLR; uint32 resrv1; uint32 resrv2; uint32 toc; uint32 parmRegs[8]; uint32 pad[2]; }; /* typedef struct TiaStackFrame64 { uint64 backChain; uint32 savedCR; uint32 resvd; uint64 savedLR; uint64 resrv1; uint64 resrv2; uint64 toc; uint64 parmRegs[8]; }; */ Address pase_GPR1(); #pragma mc_func pase_GPR1 { "38610000" } void fred_de_very_long_name_heh_what_could_this_possibly_be_when_off_the_end() { Address stk = pase_GPR1(); Address backchain; Address goforth; struct TiaStackFrame32 *frame; struct tbtable_short *tb; enum { FNOFFSET_INVALID = -1 }; // any odd number would do while (stk) { frame = (struct TiaStackFrame32 *) stk; printf("%p = %p %p %p %p %p %p %p %p %p %p %p %p\n",stk, frame->backChain, frame->savedCR, frame->savedLR, frame->toc, frame->parmRegs[0], frame->parmRegs[1], frame->parmRegs[2], frame->parmRegs[3], frame->parmRegs[4], frame->parmRegs[5], frame->parmRegs[6], frame->parmRegs[7] ); backchain = *(Address *)stk; /* looking for zero word tbtable start */ goforth = frame->savedLR; printf("lr %p\n",goforth); while (*(Address *)goforth) { goforth += sizeof(uint32); } tb = (struct tbtable_short *) goforth; printf("goforth %p version %d present %d gprs %d\n",goforth, tb->version, tb->name_present, tb->gpr_saved); if (tb->name_present) { Address nameOffset; Address fnOffset; uint32 numCtl; struct FN_NAME *fn; uint32 tb_len = 256; nameOffset = sizeof(*tb); if ((tb->fixedparms + tb->floatparms) > 0) nameOffset += sizeof(uint32); fnOffset = FNOFFSET_INVALID; if (tb->has_tboff) { fnOffset = *(uint32*)((char*)tb + nameOffset); nameOffset += sizeof(uint32); } if (tb->int_hndl) nameOffset += sizeof(uint32); if (tb->has_ctl) { numCtl = *(uint32*)((char*)tb + nameOffset); nameOffset += (sizeof(numCtl) + (numCtl * sizeof(uint32))); } if (nameOffset < (tb_len - sizeof(uint16))) { fn = (struct FN_NAME*)((char*)tb + nameOffset); if (fn->nameLen && ((nameOffset + fn->nameLen) <= (tb_len - sizeof(uint16)))) { printf("%s\n",fn->name); } } } /* printf("%p %p\n",stk, backchain); */ stk = backchain; } /* while backchain */ } int main(int argc, char * argv[]) { fred_de_very_long_name_heh_what_could_this_possibly_be_when_off_the_end(); return 0; }
-
Account Deleted run within libdb400.a of course ... but ... this sort of stuff (format pretty) ...
bash-4.3$ stackme 2ff22bc0 = 2ff22c60 0 0 0 f016c814 f016c804 2ff22c30 0 d0175968 0 0 f01757d0 lr 10000418 goforth 100005dc version 0 present 1 gprs 5 fred_de_very_long_name_heh_what_could_this_possibly_be_when_off_the_end 2ff22c60 = 2ff22ca0 0 10000658 deadbeef deadbeef deadbeef deadbeef deadbeef deadbeef a f010cb70 d010cd80 lr 10000658 goforth 1000066c version 0 present 1 gprs 0 main 2ff22ca0 = 0 20000000 10000194 2000085c 1 2ff22d28 0 0 0 0 0 0 lr 10000194 goforth 100001b4 version 0 present 1 gprs 0 __start
-
Account Deleted Ok a new "super fast" internal stack dump available for libdb400.a trace version.
; device_type=[tty,file] ; 0 - console ; 1 - file (/tmp/libdb400_trace) ; device_pid (device_type=1-file) ; 0 - /tmp/libdb400_trace ; 1 - /tmp/libdb400_trace[_pid] ; trace_type ; 0 - trace all ; 1 - trace errors only ; trace_stack ; 0 - no PASE stack dump ; 1 - PASE stack dump errors only ; 2 - PASE stack dump all ; trace_break (use with trace_stack) ; 0 - PASE internal stack (very fast, internal, recommended) ; 1 - PASE dspjob stack (slower, external, not recommended) ; 2 - PASE dbx attach stack (much slower, external, not recommended) ; cli api=[0,1] ; 0 - API ignore ; 1 - API trace
-
reporter I have loaded 1.0.3 of the cli trace tool and left the
paseclitrace.ini
file as it was in the zip.Steps to run:
export LIBPATH=/QOpenSys/download/trace-1.0.3-xlc export PASETRACE=/QOpenSys/download/trace-1.0.3-xlc/paseclitrace.ini export IBM_DB_GIL="00000000000000000000000000000000000000000000" rails s -p50000
Then i go to browser and refresh until error occurs.
Here is the trace log after producing the error.
-
Account Deleted We see and error ... SQL_INVALID_HANDLE. However with trace function only tracing errors, we can not see anything leading up to the invalid handle. Aka, speculation, could simply have been closed, possibly application and/or ibm_db, but we do not have data. Try paseclitrace.ini more data (trace_type=0, trace_stack=1, trace_break=0).
BTW -- SQLGetData as SQL_SUCCESS_WITH_INFO 1 is ok (need change trace function).
SQLNumResultCols.176822.24003072.retn SQLRETURN sqlrc 0xfffffffe (-2)
-
Account Deleted Sorry, i mean try paseclitrace.ini more data (trace_type=0, trace_stack=2, trace_break=0) ... trace everything with stack dump.
-
reporter When I set
trace_stack=2
I get a core dump/seg-fault from Ruby the first time I hit the URL, so I am not even getting to the column metadata error at this point. If I settrace_stack=1
then it doesn't core dump. Here is the pid trace log, though it shows no errors.Here is what I have
/QOpenSys/download/trace-1.0.3-xlc/paseclitrace.ini
set to:device_type=1 device_pid=1 trace_type=0 trace_stack=2 trace_break=0
-
Account Deleted Well, as you can see the Ruby "core dump" is useless (not intended to start debate). Therefore, we need to see PASE core dump ... STRSST ... look for 4700 0012 (around time failure).
We need to understand if tooling is dead (needs fix), or, we have started the hounds barking on the real issue.
BTW -- yes, this is taking time, but developing a good tool to save time later (many times), takes some real world bump and retry work. IF i had enough time i could do this all my self, but, well, just not the case.
-
reporter It's been incredibly long since I've done STRSST so I will need some guidance. Should I be using the YiPs PASEDebug page for a start? Specifically, the section labeled Part 1 — Obvious answer, job ended normally?
-
Account Deleted Wrong section ... VLOGs are not real-time "trace", but post death artifact, thereby, a VLOG "record" 4700 0012 is "added" any time PASE takes a "coredump" (any PASE application).
PASE understand VLOGS 4700 0012 (green screen STRSST/STRDST) You machine has dead PASE When PASE is guilty of dying then often times you will find static data in the VLOGS. STRSST/STRDST 1. Start a service tool 5. Licensed Internal Code log 1. Select entries from the Licensed Internal Code (LIC) log [@ Just press enter ... Type choices, press Enter. Entry ID: Starting . . . . . . . . . . . FFFFFFFF 00000000-FFFFFFFF … default options until you see list of vlogs … > 0100642A OS/400 PASE 4700 0100 07/21/11 14:55:15 9 > 0100642A OS/400 PASE 4700 0012 07/21/11 14:55:15 9 > 0100642B OS/400 PASE 4700 0013 07/21/11 14:55:17 9 Looking for ... 4700 0100 - PASE panic (all of pase dies) 4700 0012 - PASE core dump (pase process dies)
-
reporter Followed your instructions. Not seeing the PASE panic. Note: I received a core dump of the Ruby runtime before I obtained the ibm_db error, so I am not sure if the below is from the core dump or from the ibm_db error. I am guessing it is from the core dump. Note the ibm_db fetch error does NOT core dump and is instead caught and conveys a message back to the browser.
See below for the
IBM i PASE
entry that this spool file data represents.Select Entries from Licensed Internal Code Log Type options, press Enter to dump entry to selected device. 1=Printer 2=Media 5=Display entry 8=Display note Entry Major Major Minor Dump Opt ID Description Code Code Date Time K bytes 0100092B DASD support 3300 5019 08/30/15 05:12:42 1 0100092C DASD support 3300 5019 08/30/15 06:13:27 1 0100092D DASD support 3300 5019 08/30/15 06:13:29 1 0100092E DASD support 3300 5019 08/30/15 06:13:29 1 0100092F DASD support 3300 5019 08/30/15 06:13:31 1 01000930 DASD support 3300 5019 08/31/15 05:11:57 1 01000931 DASD support 3300 5019 08/31/15 05:11:57 1 01000932 DASD support 3300 5019 08/31/15 05:11:57 1 01000933 DASD support 3300 5019 08/31/15 05:11:57 1 01000934 DASD support 3300 5019 08/31/15 06:11:58 1 01000935 DASD support 3300 5019 08/31/15 06:11:58 1 01000936 DASD support 3300 5019 08/31/15 06:11:58 1 01000937 DASD support 3300 5019 08/31/15 06:11:58 1 > 01000938 IBM i PASE 4700 0012 08/31/15 14:31:30 15 Bottom
Observation: I am seeing entries for
/usr/lib/libssl.a
. I know that PowerRuby ships their ownxxxx.so
files in/PowerRuby/oss/lib
(i.e.libssl.so
andlibssl.so.1.0.0
). Not sure if this is potentially problematic because the PASE process is obviously picking up similarly named libs. -
Account Deleted Ok, Our primary core dump is illegal instruction, caused by attempting to run code near address 0x00000000. PASE/AIX intentionally zeros first few bytes of address 0x0 to catch "bad programs", usually indicating return stack corruption and/or author built/compiled badly. In this case we can see LAST STOP SIGNAL..........4 (SIGILL), clearly indicating an attempt to run code that does not exist at address zero, and, confirmation we see Instruction Address Register also at address zero (IAR=0000000000000000). Also, we see register 2 is also zero (TOC register). Humour, just too many zeros in a row to ignore, so we have found at least one "smoking gun" (SIGILL illegal instruction).
Now, comes hard part ... why did _RUBY_IBM_DB_BIND_FETCH_HELPER calling RB_HASH_ASET cause a core dump???
Speculation ... Hashes are notorious for using "performance trickery", aka, thunking "keys/addresses", so look-ups are ultra fast. So, yucky poo, is best description. However, I do not think problem will be actual ruby hash algorithm, because, if hash did not work in ruby, then the whole ruby universe would collapse like a black hole. Therefore, instead, fo love of sanity (my own), i choose to speculate a thread style interaction between ibm_db and ruby hash c code lead to eventual core dump.
What to do?? Good question. I can think of two actions ... 1) Add thread id to the key of the libdb400.a trace facility. 2) Add roll your own calls into libdb400.a trace facility, for c coders to dump some more data (this case something about hash as it relates to db2 bind).
PROGRAM: "/POWERRUBY/PRV2R1/BIN/RUBY" ARGV AT 2FF22D24 ARGV[0] "/POWERRUBY/PRV2R1/BIN/RUBY" ARGV[1] "BIN/RAILS" ARGV[2] "S" ARGV[3] "-P50000" LAST STOP SIGNAL..........4 (SIGILL) IAR=0000000000000000 LR=00000000100CBF04 ST_UPDATE+0X68 GPR00=00000000100C224C GPR01=00000000245EE450 GPR02=0000000000000000 GPR03=0000000024A5B620 ISF=245EE450 TS=8000745EE450 NIA=00000011 ***INSTRUCTION ADDRESS NOT WORD-ALIGNED*** ISF=245EE4C0 TS=8000745EE4C0 NIA=100C224C RB_HASH_ASET+0XF0 ISF=245EE530 TS=8000745EE530 NIA=D1A8F050 _RUBY_IBM_DB_BIND_FETCH_HELPER+0XEB0 ISF=245EE5F0 TS=8000745EE5F0 NIA=D1A8FBC8 IBM_DB_FETCH_ASSOC+0X98
Your observation about libssl.xxx, we see both versions in the core dump liest of files, but no idication that SSL anything was involved in the core dump. So, while unpleasant to see, and, cough, a personally satisfying i told you so to power ruby, we just don't know if this plays a role in the eventual core dump.
0 | 00033FAF | CD4CF5747D002500 | /POWERRUBY/OSS/LIB/LIBSSL.SO 0 | 00033FAF | CD4CF5747D003300 | /USR/LIB/LIBSSL.A 0 | 00033FAF | CD4CF5747D003380 | /USR/LIB/LIBCRYPTO.A
-
reporter Thanks for detailing that out.
What to do?? Good question. I can think of two actions ... 1) Add thread id to the key of the libdb400.a trace facility. 2) Add roll your own calls into libdb400.a trace facility, for c coders to dump some more data (this case something about hash as it relates to db2 bind).
Are either of those options something I can pursue given I don't (to my knowledge) have access to
libdb400.a
source code? -
Account Deleted Mmm ... Open Source... trace version libdb400.a compiled xlc to avoid gcc runtime issues (libgcc.a) ... I will think about it.
Meanwhile, can you tar a small application that demonstrates the problem? I have following versions on my machine (i don't want to load a new version unless required to recreate ) ...
bash-4.3$ ls /PowerRuby/ oss prV2R0 prV2R1
-
reporter Here is a repo you can clone.
PowerRuby hasn't released versions different from what you've specified. You should use
prV2R1
as that one errors more often (my perception), thoughprV2R0
will also error. TheREADEME.md
has setup instructions. Let me know if I've forgotten something. Very vanilla Rails app.To set version to
prV2R1
:export PATH=/PowerRuby/prV2R1/bin:$PATH
-
Account Deleted Never mind, i built my own rails test ... did not fail fetch... but ... i found coredump error(s) in new trace libdb400.a (stack overrun).
Please try this new version 1.0.4 on your machine (trace all, stack all) PASE DB2 CLI trace library
-
Account Deleted Tried your test failed rake ... do not really want to go chasing ruby gems, so how can i remove puma thing???
bash-4.3$ rake db:migrate Could not find puma-2.11.1 in any of the sources Run `bundle install` to install missing gems.
-
Account Deleted BTW -- i like this database.yml (save typing) ...
default: &default adapter: ibm_db database: "*LOCAL" username: MYID password: MYPWD development: <<: *default test: <<: *default production: <<: *default
-
reporter To use
thin
instead ofpuma
gem do the following:In Gemfile:
... #gem 'puma' gem 'thin'
cd ibmdb_fetchbug bundle install
BTW -- i like this database.yml (save typing) ...
Agreed. I mostly leave it the other way because it is generated that way for me (so zero typing :-).
Installing new trace util right now.
-
Account Deleted Nope ... all i get is the rails default page ...
Welcome aboard You’re riding Ruby on Rails!
-
reporter Latest error with new PASE CLI trace 1.0.4.
Here is the libdb400_trace_355715 log file.
Here are the flags from
/QOpenSys/download/trace-1.0.4-xlc/paseclitrace.ini
. Notetrace_stack=2
is now working.device_type=1 device_pid=1 trace_type=1 trace_stack=2 trace_break=0
Here is how I invoked it:
export LIBPATH=/QOpenSys/download/trace-1.0.4-xlc export PASETRACE=/QOpenSys/download/trace-1.0.4-xlc/paseclitrace.ini export IBM_DB_GIL="00000000000000000000000000000000000000000000" rails s -p50000
-
Account Deleted Never mind ... btu ... this never fails, no matter how many times i refresh users/1.
So ... dee ... do ... dee ... a little PowerRuby creativity during build of your copy of ibm_db ... no, can't be ... that would be unethical.
http://lp0364d:5000/users/1 Name: frog luther 22 roch mn 55906 2015-09-03 20:24:45 UTC 2015-09-03 20:24:45 UTC Edit | Back
-
reporter Nope ... all i get is the rails default page ...
1 - Navigate to http://machine:port/users
2 - Add a user or two.
3 - Navigate back to http://machine:port/users and repeatedly refresh until error happens.
-
reporter Never mind ... btu ... this never fails, no matter how many times i refresh users/1.
What PowerRuby version are you using? Also, try path
/users
instead. -
Account Deleted Never mind ...oh how do i break the news gently ... ruby guys (rails, or you) messed up and shared a hstmt resource across threads.
If you look at trace, new extra thread id field shows thread
#6using hstmt #3 ok (SQLGetData) -- but -- We look at error and thread #30 also tried to use hstmt #3 (SQLNumResultCols) ... BOOM ...Now, timestamp is moved in time, but, still, thread id
#6and #30 seem to be using the same hstmt ... that is NEVER allowed ... ever.SQLGetData.355715.1441318642.6.retn SQLRETURN sqlrc 0x1 (1) SQL_SUCCESS_WITH_INFO SQLGetData.355715.1441318642.6.parm SQLHSTMT hstmt 0x3 (3) : SQLNumResultCols.355715.1441318674.30.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLNumResultCols.355715.1441318674.30.parm SQLHSTMT hstmt 0x3 (3)
-
Account Deleted Interesting difference on my machine i am not using thin or puma ... cough ... just a thought. Maybe you should try WebBrick and see if all works ...
-
Account Deleted BTW -- using Webrick, never fails, been refreshing for long time (minutes) ...
Listing users Name Age City State Zip frog luther 22 roch mn 55906 Show Edit Destroy lex luther 42 roch mn 55906 Show Edit Destroy tod luther 48 roch mn 55906 Show Edit Destroy New User
-
reporter Good to know what the issue is. I am now researching to see if anyone else has had the hstmt sharing issue and am empty handed so far.
I took puma out of the mix and went with Webrick and get same issue/error. Here is the trace from Webrick. Btw, Webrick isn't an option for production.
$ rails s -p50000 => Booting WEBrick => Rails 4.1.8 application starting in development on http://0.0.0.0:50000 => Run `rails server -h` for more startup options => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option) => Ctrl-C to shutdown server [2015-09-03 22:47:18] INFO WEBrick 1.3.1 [2015-09-03 22:47:18] INFO ruby 2.1.5 (2014-11-13) [powerpc-aix6.1] [2015-09-03 22:47:18] INFO WEBrick::HTTPServer#start: pid=355833 port=50000
-
Account Deleted Yes, so much for Webrick theory, appears thread #3 and
#6tried to use the same hstmt ... BOOM ...Yikes, so why is my machine well behaved and yours seems bent on self destruction???
Here is my ibm_db data ... maybe yours is different???
bash-4.3$ ls -l /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so -rwxr-xr-x 1 qsys 0 750999 Nov 21 2014 /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so bash-4.3$ rails s -p5000 & [2015-09-03 15:53:55] INFO WEBrick::HTTPServer#start: pid=30234 port=5000 bash-4.3$ ps PID TTY TIME CMD 27936 pts/0 0:00 -bsh 28897 pts/0 0:00 bash 28936 pts/0 0:00 e Gemfile 30189 pts/0 0:00 e Gemfile 30234 pts/0 0:03 /PowerRuby/prV2R1/bin/ruby 30235 pts/0 0:00 ps bash-4.3$ dbx -d 100 -a 30234 Waiting to attach to process 30234 ... : ... stuff ... (dbx) map : ... stuff Entry 9: Object name: /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so Text origin: 0xd5ff5000 Text length: 0x260c2 Data origin: 0xf14e3745 Data length: 0x1033 File descriptor: 0xb
-
reporter Yikes, so why is my machine well behaved and yours seems bent on self destruction???
I've had times (measured in hours) where I tried to recreate the error and couldn't. I don't yet know the circumstances that allow for it to not happen.
$ ls -l /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so -rwxr-xr-x 1 qsys 0 750999 Mar 10 22:52 /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so
$ rails s -p50000 & [1] 355839 => Booting WEBrick => Rails 4.1.8 application starting in development on http://0.0.0.0:50000 => Run `rails server -h` for more startup options => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option) => Ctrl-C to shutdown server [2015-09-03 23:03:53] INFO WEBrick 1.3.1 [2015-09-03 23:03:53] INFO ruby 2.1.5 (2014-11-13) [powerpc-aix6.1] [2015-09-03 23:03:53] INFO WEBrick::HTTPServer#start: pid=355839 port=50000 $ ps PID TTY TIME CMD 354242 pts/1 0:00 -bash 355839 pts/1 0:02 /PowerRuby/prV2R1/bin/ruby bin/rails s -p50000 355840 pts/1 0:00 ps $ dbx -d 100 -a 355839 Waiting to attach to process 355839 ... Successfully attached to /PowerRuby/prV2R1/bin/ruby. Type 'help' for help. reading symbolic information ...internal error: assertion failed at line 5562 in file object.c internal error: assertion failed at line 5562 in file object.c . . . internal error: assertion failed at line 5562 in file object.c stopped in __fd_select at 0x2017b4bc ($t1) 0x2017b4bc (__fd_select+0xbc) 80410014 lwz r2,0x14(r1) (dbx) map . . . Entry 9: Object name: /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so Text origin: 0xd1a83000 Text length: 0x260c2 Data origin: 0x22082745 Data length: 0x1033 File descriptor: 0xb
-
reporter Continuing my research of this issue...
Currently ibm_db defaults to
connect
vspconnect
with one primary difference being thatconnect
is implicitly closed andpconnect
implicitly remains open. Would changing topconnect
fix our issue? Yes, I realize this would be a hack and not addressing the real issue of sharing a connection across threads. -
Account Deleted Well, i am not sure, but found something more important ...
The trace tool has recording 'free(s)' turned off by default, therefore, we can not detect common (mundane) problem of closing a resource, and, reusing. I do not know why i shut off free(s), but i look at this, see, if we see another pattern (*).
(*) BTW -- warning, do not breath sigh of relief, even if we figure out open/close pattern, still very, very, concerning your machine ruby is choosing to share database resources across threads, simply, a terrible idea because we would have to lock out CLI to one thread user at a time per profile, aka, rope tie rails leaving only one leg in the air twitching (... calf roping rodeo style).
-
Account Deleted Ok, here is a new trace version with free default 'on' v1.0.5 libdb400.a trace. You need to replace your pasetracecli.ini file with free elements toggled on (if using).
PASE DB2 CLI trace library At times a PASE side DB2 CLI trace is helpful. Attach:trace-1.0.5-xlc.zip 2015–09–08 (version 1.0.5) Version 1.0.5 (2015–09–08) change default for SQLFree to ‘on’ (was off)
-
reporter I've loaded
trace-1.0.5-xlc
Here are the results. Note I reproduced the error many times to give you multiple error samples (not sure if that is helpful).
Here is my paseclitrace.ini. I kept it the same as was in
trace-1.0.5-xlc.zip
except I changedtrace_stack=2
.Here's how I am invoking it:
export LIBPATH=/QOpenSys/download/trace-1.0.5-xlc export PASETRACE=/QOpenSys/download/trace-1.0.5-xlc/paseclitrace.ini export IBM_DB_GIL="00000000000000000000000000000000000000000000" rails s -p50000
-
Account Deleted No, we are only seeing errors (we already know invalid handle), we need to see good entries as well ... we are trying to see if one of the threads closed the handle, then another thread (or same) reused the closed handle (without another open).
You need to set paseclitrace.ini (trace_type=0) ...
trace_type=0 trace_stack=2
-
reporter Here is the new log with
trace_type=0
I am actively reading through the results... still digesting how these logs work. I believe the following line declares a handle of
2
being returned, correct?SQLAllocHandle.621559.1441829775.6.parm SQLSMALLINT htype 0x2 (2)
And then this line, where
2
is mentioned, is where that handle is first being used again, correct?SQLSetConnectAttr.621559.1441829775.6.walk SQLSetConnectAttr (2 2713 24a03278 fffffffd)
Or maybe a better way to say it: The above line is basically the API call with the parm values each separated with a space?
What are the
621559
and1441829775
numbers? I assume the latter is epoch time. -
Account Deleted What are the 621559 and 1441829775 numbers?
SQLSetConnectAttr.621559.1441829775.6.walk SQLSetConnectAttr - CLI API 621559 - process id or pid of trace job (aka, your ruby web server job). 1441829775 - time 6 - thread number walk - type of entry in the log (walk the stack)
the following line declares a handle of 2 being returned, correct? Incorrect, 2 type of handle created, you need to look at SQLAllocHandle manual and header file to see what '2' means.
where 2 is mentioned, is where that handle is first being used again, correct? Well, i did not look at trace, but SQLSetConnectAttr manual, yes i believe first parameter is the handle.
Unsolicited, work item... So, as you can see the trace simply records numbers for parameters, thereby any volunteer could write a python program that scanned filled in the header file names for the "known" #define numbers ... cough ... any one could do that ... cough, cough, anyone at all ... cough ... not a hint to anyone in particular ... cough, cough, cough.
-
Account Deleted So for education, here is an interesting sequence ...
We see SQLExecDirect use SQLHSTMT hstmt 0x3 (cool), then ruby finalize_list calls through to SQLFreeHandle htype 0x3/hndl 0x3 (mmmm ... ok), then finalize_list AGAIN calls through to SQLFreeHandle htype 0x3/hndl 0x3 and BOOM sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR).
SQLExecDirect.621559.1441829776.6.tbeg +++success+++ SQLExecDirect.621559.1441829776.6.walk dump_SQLExecDirect (0 3 24a2ea10 10) SQLExecDirect.621559.1441829776.6.walk SQLExecDirect (3 24a2ea10 10) SQLExecDirect.621559.1441829776.6.walk _ruby_ibm_db_SQLExecDirect_helper (?) SQLExecDirect.621559.1441829776.6.walk ibm_db_exec (?) SQLExecDirect.621559.1441829776.6.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS SQLExecDirect.621559.1441829776.6.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.621559.1441829776.6.tbeg +++success+++ SQLFreeHandle.621559.1441829776.6.walk dump_SQLFreeHandle (0 30003 3) SQLFreeHandle.621559.1441829776.6.walk SQLFreeHandle (30003 3) SQLFreeHandle.621559.1441829776.6.walk _ruby_ibm_db_free_stmt_struct (?) SQLFreeHandle.621559.1441829776.6.walk finalize_list (?) SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS SQLFreeHandle.621559.1441829776.6.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829776.6.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829776.6.tbeg ---error--- SQLFreeHandle.621559.1441829776.6.walk dump_SQLFreeHandle (fffffffe 30003 3) SQLFreeHandle.621559.1441829776.6.walk SQLFreeHandle (30003 3) SQLFreeHandle.621559.1441829776.6.walk _ruby_ibm_db_free_stmt_struct (?) SQLFreeHandle.621559.1441829776.6.walk finalize_list (?) SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829776.6.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829776.6.parm SQLINTEGER hndl 0x3 (3)
-
Account Deleted Last entry "interesting" ...
Reason this is interesting is that it is very easy to imagine scenarios where this double free results in unintentional free of a working handle in CLI. Expert knowledge (mine), IBM i CLI re-uses lowest number handle it can find, therefore in a mutli thread environment using DB2 'handles' (like rails), very easy to 'make up' scenarios where one thread has done a allocation that 're-used" a number timed between the first and second delete and lost a perfectly good handle.
-
Account Deleted BTW -- i have not looked through all the data yet, so we do not know the double free is the "nad actor", but it is a smoking gun, therefore for education "how do i read trace", this is a good abstract conversation.
-
Account Deleted BTW -- sequences that look like this may me VERY uncomfortable (RUBY CRAZY) ... aka ... i have no idea what a rb_postponed_job_flush actually does, but the garbage collector fires gc_finalize_deferred, which eventually calls SQLFreeHandle and BOOM SQL_INVALID_HANDLE (SQL_ERROR).
Not saying is problem yet, but anything in garbage collection that runs "defered", especially with a double free already identified is just asking for big toruble.
SQLFreeHandle.621559.1441829897.19.tbeg ---error--- SQLFreeHandle.621559.1441829897.19.walk dump_SQLFreeHandle (fffffffe 30003 3) SQLFreeHandle.621559.1441829897.19.walk SQLFreeHandle (30003 3) SQLFreeHandle.621559.1441829897.19.walk _ruby_ibm_db_free_stmt_struct (?) SQLFreeHandle.621559.1441829897.19.walk finalize_list (?) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.walk rb_postponed_job_flush (?) SQLFreeHandle.621559.1441829897.19.walk rb_threadptr_execute_interrupts.part.38 (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
-
Account Deleted Mmm ... downloaded you trace file ... only SQL_ERROR i see are all SQL_ERROR. Did this actually fail??? I though your other file had error in SQLGetData (or something)???
[adc@oc7083008330 aaron-2015-06-24]$ grep SQL_ERROR trace-2015-09-10.txt SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829877.14.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
-
Account Deleted I had to look back through this issue to find it was SQLNumResultCols (not SQLGetData), but again, latest trace all we see is SQL_ERROR on SQL_ERROR. Did this actually fail???
SQLNumResultCols.355715.1441318674.30.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
-
Account Deleted Sorry ... did you test really fail, aka, not return rows of data (original issue)???
Old trace SQLNumResultCols ... SQL_INVALID_HANDLE (SQL_ERROR)
SQLNumResultCols.355715.1441318674.30.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
New trace ... only SQLFreeHandle SQL_INVALID_HANDLE (SQL_ERROR)
[adc@oc7083008330 aaron-2015-06-24]$ grep SQL_ERROR trace-2015-09-10.txt SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829877.14.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
-
reporter I had to look back through this issue to find it was SQLNumResultCols (not SQLGetData), but again, latest trace all we see is SQL_ERROR on SQL_ERROR. Did this actually fail???
My fault. I was monitoring the trace file with a
grep
to look for "error" and not watching what error was actually produced. Sorry for wasting your time.Here is the log with
SQLNumResultCols
error. Had to put it on my personal server because bitbucket told me it was too large for their Snippets (20MB). Line 268,937 is one instance of the error.We see SQLExecDirect use SQLHSTMT hstmt 0x3 (cool), then ruby finalize_list calls through to SQLFreeHandle htype 0x3/hndl 0x3 (mmmm ... ok), then finalize_list AGAIN calls through to SQLFreeHandle htype 0x3/hndl 0x3 and BOOM sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR).
Which then begs the question, is it our ibm_db implementation that is combining multiple
SQLExecDirect
statements into a single handle when ActiveRecord was expecting them to be separate? Or maybe a different way to ask the same question: When the web transaction completes are there handles still open that should be closed?Unsolicited, work item... So, as you can see the trace simply records numbers for parameters, thereby any volunteer could write a python program that scanned filled in the header file names for the "known" #define numbers ... cough ... any one could do that ... cough, cough, anyone at all ... cough ... not a hint to anyone in particular ... cough, cough, cough.
I definitely caught your hint :-) ...but am not exactly sure what you envision the end result accomplishing. Is it so we can more easily know which line of code in ibm_db.c is causing the error?
-
Account Deleted Well, here is the smoking gun ... breifly ... i do not see the characteristic double free, so this may be the case were the double delete gets out of sequence
1) SQLExecDirect worked fine hstmt 0x3 2) rb_threadptr_execute_interrupts->rb_postponed_job_flush->_ruby_ibm_db_free_stmt_struct->SQLFreeHandle hndl 0x3 (3) 3) BOOM ... SQLNumResultCols hstmt 0x3 (3)
cut/paste from trace, these are back-2-back entries ...
good, good, ... SQLExecDirect.638756.1441906535.73.tbeg +++success+++ SQLExecDirect.638756.1441906535.73.walk dump_SQLExecDirect (0 3 23b0e770 1a) SQLExecDirect.638756.1441906535.73.walk SQLExecDirect (3 23b0e770 1a) SQLExecDirect.638756.1441906535.73.walk _ruby_ibm_db_SQLExecDirect_helper (?) SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?) SQLExecDirect.638756.1441906535.73.walk call_cfunc_m1 (?) SQLExecDirect.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLExecDirect.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.638756.1441906535.73.tbeg +++success+++ SQLFreeHandle.638756.1441906535.73.walk dump_SQLFreeHandle (0 30003 3) SQLFreeHandle.638756.1441906535.73.walk SQLFreeHandle (30003 3) SQLFreeHandle.638756.1441906535.73.walk _ruby_ibm_db_free_stmt_struct (?) SQLFreeHandle.638756.1441906535.73.walk finalize_list (?) SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906535.73.walk rb_postponed_job_flush (?) SQLFreeHandle.638756.1441906535.73.walk rb_threadptr_execute_interrupts.part.38 (?) SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLNumResultCols using a handle that was already closed SQLNumResultCols.638756.1441906535.73.tbeg ---error--- SQLNumResultCols.638756.1441906535.73.walk dump_SQLNumResultCols (fffffffe 3 22888e54) SQLNumResultCols.638756.1441906535.73.walk SQLNumResultCols (3 22888e54) SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_SQLNumResultCols_helper (?) SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_get_result_set_info (?) SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) next we see a reallocation of stamt handle #3 (too late for SQLNumResultCols) SQLAllocHandle.638756.1441906535.73.tbeg +++success+++ SQLAllocHandle.638756.1441906535.73.walk dump_SQLAllocHandle (0 30003 2 23b1a834) SQLAllocHandle.638756.1441906535.73.walk SQLAllocHandle (30003 2 23b1a834) SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?) SQLAllocHandle.638756.1441906535.73.walk call_cfunc_m1 (?) SQLAllocHandle.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLAllocHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLAllocHandle.638756.1441906535.73.parm SQLINTEGER ihnd 0x2 (2) SQLAllocHandle.638756.1441906535.73.parm SQLINTEGER* ohnd 0x23b1a834 (598845492) SQLAllocHandle.638756.1441906535.73.phex 23b1a834 : 00000003
-
Account Deleted BTW --
Ruby script initiated functions stack call_cfunc_m1->(ibm_db_exec, ibm_db_result_cols, ibm_db_result_cols)
-- but --
Ruby garbage collector initiated functions with stack gc_finalize_deferred->..-> (_ruby_ibm_db_free_stmt_struct).
Very interesting, possible ruby garbage collecting is in fact the actual problem for both double delete and out of sequence release.
-
Account Deleted Ruby garbage collection would relate back to "script scope" (i think), where out of scope object could be "collected". So, possibilities (may be wrong), perhaps needed something in ibm_db.c code saying "ruby ref count leave me alone" (i doubt), or , Ruby script has hand on a stmt that goes out of scope and is free (garbage collected). Can you check the ruby script code for scope of the statement object ???
When the Ruby garbage collector is invoked, it has a mark phase and a sweep phase. The mark phase marks all objects in the system by marking: all objects referenced by a ruby stack frame (e.g. local variables) all globally accessible objects (e.g. referred to by a constant or global variable) and their children/referents, and all objects referred to by a reference on the stack, as well as those objects' children/referents. as well as a number of other objects that are not important to this discussion. The sweep phase then destroys any objects that are not accessible (i.e. those that were not marked).
-
reporter Ok, so this entry is full of observations.
First I reviewed class level variables (i.e. @@).
Line 3186, variable
@@open_classing_done
. I believe this is the only class variable used in ibm_db_adapter.rb.Moving on...
Most Ruby methods in
ibm_db_adapter.rb
obtain a local variable forstmt
(orpstmt
) and release it (i.e.IBM_DB.free_stmt(stmt) if stmt
) in the same method, except thefetch_data
method below. It receives astmt
allocated upstream, inexecute
orexec_query
and does afree_stmt(...)
within vs. letting the caller do it. As best I can tell the caller'sstmt
variable would still be valid, though the handle it once contained is no longer valid. Again, an observation.def fetch_data(stmt) if(stmt) begin return @servertype.select(stmt) rescue StandardError => fetch_error # Handle driver fetch errors error_msg = IBM_DB.getErrormsg(stmt, IBM_DB::DB_STMT ) if error_msg && !error_msg.empty? raise StatementInvalid,"Failed to retrieve data: #{error_msg}" else error_msg = "An unexpected error occurred during data retrieval" error_msg = error_msg + ": #{fetch_error.message}" if !fetch_error.message.empty? raise error_msg end ensure # Ensures to free the resources associated with the statement IBM_DB.free_stmt(stmt) if stmt end end end
It should be noted
fetch_data()
is only invoked from theselect
method. Theselect
method, below, procures astmt
handle but never does afree_stmt
, becausefetch_data()
does. I bring this up because I know RPG, at some point in time, had issues with pointers (variables?) that were allocated in one sub proc and deallocated in another (don't recall exact details, but I was bitten by it).def select(sql, name = nil, binds = []) # Replaces {"= NULL" with " IS NULL"} OR {"IN (NULL)" with " IS NULL"} sql.gsub!( /(=\s*NULL|IN\s*\(NULL\))/i, " IS NULL" ) results = [] if(binds.nil? || binds.empty?) stmt = execute(sql, name) else stmt = exec_query(sql, name, binds) end cols = IBM_DB.resultCols(stmt) if( stmt ) results = fetch_data(stmt) end if(@isAr3) return results else return ActiveRecord::Result.new(cols, results) end end
Method
exec_query
procuresstmt
and returns it to caller. The aboveselect
method is one such caller, but notice howreturn false
is used instead of raising an exception likeexecute
does.def exec_query(sql, name = 'SQL', binds = []) begin param_array = binds.map do |column,value| quote_value_for_pstmt(value, column) end stmt = prepare(sql, name) if( stmt ) if(execute_prepared_stmt(stmt, param_array)) return stmt end else return false end ensure @offset = @limit = nil end end
There's potentially some funny stuff going on in method
last_generated
, show below. Note how it states the passed instmt
is used for IDS but not for DB2. Well, it does aIBM_DB.free_stmt
regardless of whether DB2 or IDS is being used. Might account for the SQLFreeHandle SQL_INVALID_HANDLE (SQL_ERROR) we saw earlier? Though my code should not be calling this as I am doing SELECTs and not INSERTs.# Returns the last automatically generated ID. # This method is required by the +insert+ method # The "stmt" parameter is ignored for DB2 but used for IDS def last_generated_id(stmt) # Queries the db to obtain the last ID that was automatically generated sql = "SELECT IDENTITY_VAL_LOCAL() FROM SYSIBM.SYSDUMMY1" stmt = IBM_DB.prepare(@adapter.connection, sql) if(stmt) if(IBM_DB.execute(stmt, nil)) begin # Fetches the only record available (containing the last id) IBM_DB.fetch_row(stmt) # Retrieves and returns the result of the query with the last id. IBM_DB.result(stmt,0) rescue StandardError => fetch_error # Handle driver fetch errors error_msg = IBM_DB.getErrormsg(stmt, IBM_DB::DB_STMT ) if error_msg && !error_msg.empty? raise "Failed to retrieve last generated id: #{error_msg}" else error_msg = "An unexpected error occurred during retrieval of last generated id" error_msg = error_msg + ": #{fetch_error.message}" if !fetch_error.message.empty? raise error_msg end ensure # Free resources associated with the statement IBM_DB.free_stmt(stmt) if stmt end else error_msg = IBM_DB.getErrormsg(stmt, IBM_DB::DB_STMT ) IBM_DB.free_stmt(stmt) if stmt if error_msg && !error_msg.empty? raise "Failed to retrieve last generated id: #{error_msg}" else error_msg = "An unexpected error occurred during retrieval of last generated id" raise error_msg end end else error_msg = IBM_DB.getErrormsg(@adapter.connection, IBM_DB::DB_CONN ) if error_msg && !error_msg.empty? raise "Failed to retrieve last generated id due to error: #{error_msg}" else raise StandardError.new('An unexpected error occurred during retrieval of last generated id') end end end
Is this the type of research you were looking for?
Side comment: There is A LOT of extra code in
ibm_db_adapter.rb
that has nothing to do with our implementation (i.e. classes IBM_IDS, IBM_DB2_ZOS_8, IBM_DB2_ZOS, IBM_DB2_LUW_COBRA, etc). Given some Ruby methods override the abstract/base class methods it makes it all the more cumbersome to search for things easily. Wondering what your thoughts are of removing these sections of code? -
Account Deleted Removing code (not IBM i platform) ... mmm ... well ... gee ... more than bit of politics ...
First, if we stray too far, we may never merge back into more global IBM repository.
However, at times, i suspect our version may work better remote Linux/Windows to IBM i, because we are interested in IBM i working. So, i guess our folks would not be much interested in Z/OS, and, we likely only interested in LUW DB2 Connect to IBM i (not LUW DB2 per say). SO, if you think you can find the limbs to trim and still have allow the Windows/Linux connect to IBM i emote (via DB2 Connect), then ... ok.
-
Account Deleted As far as ibm_db_adapter.rb research ... yes
I have not had time to think about your observations, so bit unwise to offer suggestion, but ...
Suggestion, i wonder if you added a bit of ruby print code to dump/output with similar time stamps to the trace log ... maybe you will see correlations.
-
reporter Suggestion, i wonder if you added a bit of ruby print code to dump/output with similar time stamps to the trace log ... maybe you will see correlations.
I added
rake
task "trace:run" to the ibmdb_fetchbug repo to use theTracePoint
class for getting in-depth call stacks. To run you do the following:$ cd ibmdb_fetchbug $ rake trace:run
NOTE: This doesn't reproduce the error and is instead a bit of code we can use in
ibm_db_adapter.rb
(I need to get some other stuff out the door, but wanted to convey this to help both of us).You can change
ibmdb_fetchbug/lib/task/trace.rake
to have different types of output. I limited it to justibm_db_adapter.rb
(hard coded) for now. note it also allows tracing of Ruby-to-C calls.Here is the output. Log layout is <classname>.<method_name>:<lineno>:<epoch>.<Thread.current.object_id>
% rake trace:run Query results... #<Class:ActiveRecord::Base>.ibm_db_connection:281.1442261472.271838790 ActiveRecord::ConnectionAdapters::TableDefinition.initialize:711.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.initialize:890.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2_I5.initialize:3231.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.initialize:2621.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.initialize:2169.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2294.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1575.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2278.1442261472.271838790 Arel::Visitors::ToSql.initialize:3755.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1086.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1131.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1137.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1094.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2294.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1575.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2278.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.to_sql:1050.1442261472.271838790 Arel::Visitors::IBM_DB.visit_Arel_Nodes_SelectStatement:3776.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.quote_column_name:1854.1442261472.271838790 ActiveRecord::ConnectionAdapters::HostedDataServer.check_reserved_words:3108.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.add_limit_offset!:1706.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.query_offset_limit:2947.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.select:1273.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1575.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2278.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.fetch_data:1236.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.select:2208.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.columns:2058.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2_I5.columns:3317.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DataServer.columns:2531.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.serverschema:882.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.tables:1977.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.primary_key:2018.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 asdf ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790 asdfasdf
-
Account Deleted Mmm ... i don't understand. Any "ruby service" that no longer reproduces the error is lost on me.
Again, reminder, my machine does not reproduce this error (ever), so anything done for this issue, tools and/or actual debug, needs to take place on your machine.
-
Account Deleted Just a thought ... WE have identified ruby garbage collection (gc) on your machine appears overly aggressive throwing out trash, this case, our DB2 statements. Funny part, this does not happen on my machine (ever). Obvious speculation, your version of Ruby is different than mine, possibly newer than my version of Ruby.
Ruby gc wants to play "rough", perhaps we should modify ruby c code so ruby can't throw out our statements, aka, we take out our own trash. Today (i think), we are using correct ruby c Data_Wrap_Struct, maybe take drastic action to get out of ruby garbage collection issue with c code (very sad day for ruby however).
SQLFreeHandle.638756.1441906535.73.tbeg +++success+++ SQLFreeHandle.638756.1441906535.73.walk dump_SQLFreeHandle (0 30003 3) SQLFreeHandle.638756.1441906535.73.walk SQLFreeHandle (30003 3) SQLFreeHandle.638756.1441906535.73.walk _ruby_ibm_db_free_stmt_struct (?) SQLFreeHandle.638756.1441906535.73.walk finalize_list (?) SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906535.73.walk rb_postponed_job_flush (?) SQLFreeHandle.638756.1441906535.73.walk rb_threadptr_execute_interrupts.part.38 (?) SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
-
reporter Here is some version info from two different machines that both have the error. I am definitely using a later version that you are (unless they gave you v1.0.8), but I've also been able to recreate on both versions.
##Customer Machine with PowerRuby
v1.0.7
$ /PowerRuby/prV2R0/bin/ruby -v ruby 2.0.0p598 (2014-11-13 revision 48408) [powerpc-aix6.1.0.0] ***they don't have prV2R1 installed per my recommendation at the time***
##KrengelTech machine at
v1.0.8
(latest release, though not available to public to my knowledge)$ /PowerRuby/prV2R0/bin/ruby -v ruby 2.0.0p643 (2015-02-25 revision 49749) [powerpc-aix6.1.0.0] $ /PowerRuby/prV2R1/bin/ruby -v ruby 2.1.5p273 (2014-11-13 revision 48405) [powerpc-aix6.1]
Could you convey your ruby versions back to this thread so we can have it noted?
maybe take drastic action to get out of ruby garbage collection issue with c code (very sad day for ruby however).
I think PowerRuby team would need to be involved with that as they hold the compile process.
Besides, I thought garbage collection wasn't really the issue and instead you said handles should never be shared across threads? Or is it possible we have two issues?
##Access to a machine On final note, I now have our Litmis Spaces effort in beta and you could sign up for an account so you can be working with an environment that produces the error. Here is a mp4 video (100MB download) that shows how to setup an account. You'd select a PowerRuby environment instead of a Node.js one. And then
git clone git@bitbucket.org:aaronbartell/ibmdb_fetchbug.git
to get the code. And then replace the `database.yml' in folder ibmdb_fetchbug with the one that was generated for you (dynamically named directory in your /home directory). Or sign up for an account and I can configure everything for you. -
Account Deleted My version ... appears to match your customer, assuming customer sees 'the' problem??
bash-4.3$ /PowerRuby/prV2R0/bin/ruby -v ruby 2.0.0p598 (2014-11-13 revision 48408) [powerpc-aix6.1.0.0]
-
reporter Yes, they are aware of the problem and monitoring this thread.
-
Account Deleted Two issues or multiple thread issue ... Well, another cut of trace data ...
We may use SQLAllocEnv as start point for any "web request", env alloc is first thing happens in ibm_db. I removed front part of data becasue only thread
#6was running (and all worked). Unfortunately, later, we see multiple threads acting on DB2 resources. In truth, if all thread DB2 use synchronized correctly (moon blue, ok tuesday, but not firday, etc.), threads could share resource. But, Ruby/Rails wants I/O operations to happen without holding the GIL, so, Ruby/Rails should never share resources like DB2 (any other PHD disagree yapping is likely rooted in dude that only knows MySql -- limited experience).So, i do not see the multi-thread smoking gun in the data below, even when factoring multiple threads. However, we can see Ruby garbage collector apparently toss out a perfectly good hstmt, and, next SQL operatin try to use it.
BTW -- sifting between topics here at lab, so maybe you see a pattern that let's ruby gc off the hook, i am failing to find. yes, i agree, seems like ruby could not get this garbage collecting thing wrong, so i hope, hope, hope, this is something stupid in ibm_db.
> grep "hstmt 0x3\|hndl 0x3\|htype 0x3\|walk ibm\|walk gc/|SQL_ERROR" trace-2015-09-10.txt : SQLAllocEnv.621559.1441829785.6.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829785.6.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829785.6.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829785.6.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829785.6.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829785.6.walk ibm_db_connect (?) SQLConnect.621559.1441829785.6.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829785.6.walk ibm_db_connect (?) SQLGetInfo.621559.1441829785.6.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829785.6.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829785.6.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829785.6.walk ibm_db_exec (?) SQLExecDirect.621559.1441829785.6.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829785.12.walk ibm_db_close (?) SQLFreeHandle.621559.1441829785.12.walk ibm_db_close (?) SQLFreeHandle.621559.1441829785.12.walk ibm_db_close (?) SQLAllocEnv.621559.1441829785.12.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829785.12.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829785.12.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829785.12.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829785.12.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829785.12.walk ibm_db_connect (?) SQLConnect.621559.1441829785.12.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829785.12.walk ibm_db_connect (?) SQLGetInfo.621559.1441829785.12.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829785.12.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829785.12.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829785.12.walk ibm_db_exec (?) SQLExecDirect.621559.1441829785.12.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829785.8.walk ibm_db_close (?) SQLFreeHandle.621559.1441829785.8.walk ibm_db_close (?) SQLFreeHandle.621559.1441829785.8.walk ibm_db_close (?) SQLAllocEnv.621559.1441829785.8.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829785.8.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829785.8.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829785.8.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829785.8.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829785.8.walk ibm_db_connect (?) SQLConnect.621559.1441829785.8.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829785.8.walk ibm_db_connect (?) SQLGetInfo.621559.1441829785.8.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829785.8.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829785.8.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829785.8.walk ibm_db_exec (?) SQLExecDirect.621559.1441829785.8.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829876.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829876.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829876.13.walk ibm_db_close (?) SQLAllocEnv.621559.1441829876.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829876.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829876.13.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829876.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829876.13.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829876.13.walk ibm_db_connect (?) SQLConnect.621559.1441829876.13.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829876.13.walk ibm_db_connect (?) SQLGetInfo.621559.1441829876.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829876.13.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829876.13.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829876.13.walk ibm_db_exec (?) SQLExecDirect.621559.1441829876.13.parm SQLHSTMT hstmt 0x3 (3) SQLAllocHandle.621559.1441829876.13.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829876.13.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829876.13.walk ibm_db_exec (?) SQLNumResultCols.621559.1441829876.13.walk ibm_db_result_cols (?) SQLBindCol.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLBindCol.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLBindCol.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLFetch.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLFetch.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLFetch.621559.1441829876.13.walk ibm_db_fetch_array (?) SQLFreeHandle.621559.1441829876.13.walk ibm_db_free_stmt (?) SQLFreeHandle.621559.1441829876.13.parm SQLSMALLINT htype 0x3 (3) SQLDisconnect.621559.1441829877.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.13.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLConnect.621559.1441829877.13.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.13.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.13.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.13.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.13.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829877.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.13.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLConnect.621559.1441829877.13.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.13.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.13.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.13.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.13.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.621559.1441829877.14.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829877.14.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829877.14.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829877.14.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829877.14.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829877.14.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829877.14.parm SQLINTEGER hndl 0x3 (3) SQLDisconnect.621559.1441829877.14.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.14.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.14.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.14.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.14.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.14.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.14.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.14.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.14.walk ibm_db_connect (?) SQLConnect.621559.1441829877.14.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.14.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.14.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.14.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.14.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.14.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.14.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829877.15.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.15.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.15.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.15.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.15.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.15.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.15.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.15.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.15.walk ibm_db_connect (?) SQLConnect.621559.1441829877.15.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.15.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.15.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.15.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.15.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.15.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.15.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829877.16.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.16.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.16.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.16.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.16.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.16.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.16.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.16.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.16.walk ibm_db_connect (?) SQLConnect.621559.1441829877.16.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.16.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.16.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.16.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.16.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.16.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.16.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829877.17.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.17.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.17.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.17.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.17.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.17.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.17.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.17.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.17.walk ibm_db_connect (?) SQLConnect.621559.1441829877.17.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.17.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.17.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.17.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.17.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.17.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.17.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829877.18.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.18.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.18.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.18.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.18.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.18.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.18.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.18.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.18.walk ibm_db_connect (?) SQLConnect.621559.1441829877.18.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.18.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.18.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.18.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.18.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.18.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.18.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829877.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?) SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?) SQLAllocEnv.621559.1441829877.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.13.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLConnect.621559.1441829877.13.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?) SQLGetInfo.621559.1441829877.13.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829877.13.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829877.13.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829877.13.walk ibm_db_exec (?) SQLExecDirect.621559.1441829877.13.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829897.19.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.19.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.19.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLConnect.621559.1441829897.19.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.19.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.19.parm SQLHSTMT hstmt 0x3 (3) SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?) SQLNumResultCols.621559.1441829897.19.walk ibm_db_result_cols (?) SQLBindCol.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLBindCol.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLBindCol.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLFetch.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLFetch.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLFetch.621559.1441829897.19.walk ibm_db_fetch_array (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_free_stmt (?) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLDisconnect.621559.1441829897.19.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.19.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.19.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_connect (?) SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3) SQLConnect.621559.1441829897.19.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.19.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.19.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829897.20.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.20.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.20.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLConnect.621559.1441829897.20.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.20.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.20.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.20.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.20.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.20.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.621559.1441829897.21.walk gc_finalize_deferred (?) SQLFreeHandle.621559.1441829897.21.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.621559.1441829897.21.parm SQLINTEGER hndl 0x3 (3) SQLDisconnect.621559.1441829897.21.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.21.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.21.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLConnect.621559.1441829897.21.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.21.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.21.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.21.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.21.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.21.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829897.22.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.22.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.22.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.22.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.22.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.22.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.22.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.22.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.22.walk ibm_db_connect (?) SQLConnect.621559.1441829897.22.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.22.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.22.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.22.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.22.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.22.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.22.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829897.19.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.19.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.19.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLConnect.621559.1441829897.19.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.19.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.19.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829897.20.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.20.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.20.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLConnect.621559.1441829897.20.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.20.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.20.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.20.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.20.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.20.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829897.21.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?) SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?) SQLAllocEnv.621559.1441829897.21.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.21.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLConnect.621559.1441829897.21.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?) SQLGetInfo.621559.1441829897.21.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829897.21.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829897.21.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829897.21.walk ibm_db_exec (?) SQLExecDirect.621559.1441829897.21.parm SQLHSTMT hstmt 0x3 (3) SQLDisconnect.621559.1441829898.22.walk ibm_db_close (?) SQLFreeHandle.621559.1441829898.22.walk ibm_db_close (?) SQLFreeHandle.621559.1441829898.22.walk ibm_db_close (?) SQLAllocEnv.621559.1441829898.22.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829898.22.walk ibm_db_connect (?) SQLGetEnvAttr.621559.1441829898.22.walk ibm_db_connect (?) SQLSetEnvAttr.621559.1441829898.22.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829898.22.walk ibm_db_connect (?) SQLSetConnectAttr.621559.1441829898.22.walk ibm_db_connect (?) SQLConnect.621559.1441829898.22.walk ibm_db_connect (?) SQLGetConnectAttr.621559.1441829898.22.walk ibm_db_connect (?) SQLGetInfo.621559.1441829898.22.walk ibm_db_connect (?) SQLAllocHandle.621559.1441829898.22.walk ibm_db_exec (?) SQLAllocHandle.621559.1441829898.22.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.621559.1441829898.22.walk ibm_db_exec (?) SQLExecDirect.621559.1441829898.22.parm SQLHSTMT hstmt 0x3 (3) [adc@oc7083008330 aaron-2015-06-24]$
-
Account Deleted Yes, they are aware of the problem and monitoring this thread
Wait a minute, you did not really answer the question.
Does this customer, see this issue, using the same version Ruby that i am using (older version)???
This is not the time for political correct, we have to know the difference between "i thought i heard about a issue", and, "i bloody well have this issue".
Do you understand?
-
reporter Sorry, yes, customer has this issue. I have access to their machine and can reproduce the error on their machine. So this is a "I bloody well have this issue". Actually, I've verified this error on multiple customer machines that have the same version you have (PowerRuby v1.0.7)
Again let me know if you want to get access to a machine (Litmis Spaces) where this error can be reproduced so you can see the error first hand.
-
Account Deleted Sorry, cut/paste wrong data (issue is still same) ...
SQLAllocEnv.638756.1441906534.69.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906534.69.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906534.69.walk ibm_db_connect (?) SQLSetEnvAttr.638756.1441906534.69.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906534.69.walk ibm_db_connect (?) SQLSetConnectAttr.638756.1441906534.69.walk ibm_db_connect (?) SQLConnect.638756.1441906534.69.walk ibm_db_connect (?) SQLGetConnectAttr.638756.1441906534.69.walk ibm_db_connect (?) SQLGetInfo.638756.1441906534.69.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906534.69.walk ibm_db_exec (?) SQLAllocHandle.638756.1441906534.69.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.638756.1441906534.69.walk ibm_db_exec (?) SQLExecDirect.638756.1441906534.69.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.638756.1441906534.69.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906534.69.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906534.69.parm SQLINTEGER hndl 0x3 (3) SQLDisconnect.638756.1441906534.68.walk ibm_db_close (?) SQLFreeHandle.638756.1441906534.68.walk ibm_db_close (?) SQLFreeHandle.638756.1441906534.68.walk ibm_db_close (?) SQLAllocEnv.638756.1441906534.68.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906534.68.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906534.68.walk ibm_db_connect (?) SQLSetEnvAttr.638756.1441906534.68.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906534.68.walk ibm_db_connect (?) SQLSetConnectAttr.638756.1441906534.68.walk ibm_db_connect (?) SQLConnect.638756.1441906534.68.walk ibm_db_connect (?) SQLGetConnectAttr.638756.1441906534.68.walk ibm_db_connect (?) SQLGetInfo.638756.1441906534.68.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906534.68.walk ibm_db_exec (?) SQLAllocHandle.638756.1441906534.68.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.638756.1441906534.68.walk ibm_db_exec (?) SQLExecDirect.638756.1441906534.68.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.638756.1441906534.68.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906534.68.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906534.68.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.638756.1441906534.68.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906534.68.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.638756.1441906534.68.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906534.68.parm SQLINTEGER hndl 0x3 (3) SQLDisconnect.638756.1441906534.71.walk ibm_db_close (?) SQLFreeHandle.638756.1441906534.71.walk ibm_db_close (?) SQLFreeHandle.638756.1441906534.71.walk ibm_db_close (?) SQLAllocEnv.638756.1441906534.71.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906534.71.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906534.71.walk ibm_db_connect (?) SQLSetEnvAttr.638756.1441906534.71.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906534.71.walk ibm_db_connect (?) SQLSetConnectAttr.638756.1441906534.71.walk ibm_db_connect (?) SQLConnect.638756.1441906534.71.walk ibm_db_connect (?) SQLGetConnectAttr.638756.1441906534.71.walk ibm_db_connect (?) SQLGetInfo.638756.1441906534.71.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906534.71.walk ibm_db_exec (?) SQLAllocHandle.638756.1441906534.71.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.638756.1441906534.71.walk ibm_db_exec (?) SQLExecDirect.638756.1441906534.71.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.638756.1441906534.71.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906534.71.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906534.71.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLDisconnect.638756.1441906535.73.walk ibm_db_close (?) SQLFreeHandle.638756.1441906535.73.walk ibm_db_close (?) SQLFreeHandle.638756.1441906535.73.walk ibm_db_close (?) SQLAllocEnv.638756.1441906535.73.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906535.73.walk ibm_db_connect (?) SQLGetEnvAttr.638756.1441906535.73.walk ibm_db_connect (?) SQLSetEnvAttr.638756.1441906535.73.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906535.73.walk ibm_db_connect (?) SQLSetConnectAttr.638756.1441906535.73.walk ibm_db_connect (?) SQLConnect.638756.1441906535.73.walk ibm_db_connect (?) SQLGetConnectAttr.638756.1441906535.73.walk ibm_db_connect (?) SQLGetInfo.638756.1441906535.73.walk ibm_db_connect (?) SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?) SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?) SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?) SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?) SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?) SQLNumResultCols.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetDiagRec.638756.1441906535.73.walk ibm_db_result_cols (?) SQLGetDiagRec.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLGetDiagRec.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?) SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?) SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?) SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLBindCol.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLBindCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLBindCol.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLBindCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLBindCol.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLBindCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLFetch.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLFetch.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLFetch.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLFetch.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLFetch.638756.1441906535.73.walk ibm_db_fetch_array (?) SQLFetch.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLFreeHandle.638756.1441906535.73.walk ibm_db_free_stmt (?) SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?) SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3) SQLDisconnect.638756.1441906535.74.walk ibm_db_close (?) SQLFreeHandle.638756.1441906535.74.walk ibm_db_close (?) SQLFreeHandle.638756.1441906535.74.walk ibm_db_close (?)
-
Account Deleted Well, "first hand" is not my real objective. What we need is tooling, like our trace, that puts the "collecting of data" into the art of the possible, without jumping on every machine. However, trial case this, we are starting to see value of PASE side trace tool taking shape (DB2-side monitor/trace would never even get close).
-
Account Deleted BTW -- trace analysis, you can see fancy grep statement i am using to pull data from the trace ... i am on a Linux machine, so grep is probably more powerful than AIX or PASE (not 100% sure you can do).
grep "hstmt 0x3\|hndl 0x3\|htype 0x3\|walk ibm\|walk gc\|SQL_ERROR" trace-2015-09-10-2.txt
-
reporter Well, "first hand" is not my real objective.
Fair enough. I do believe this thread will be visited often to learn the approach to deep PASE debugging (your greater intention). So now we need next steps ideas. One I can do is modify
ibm_db_adapter.rb
to have a TracePoint like I did for the trace:run rake task. This would give us method execution order from the Ruby side of things and might produce some "aha's".Do you agree this is a good next step?
-
Account Deleted Mmm ... maybe you see this ... but i am not sure i can synchronize/match trace log entries with rake trace. How would this be done?
We know invalid handle occurred due to a Ruby script call ibm_db_result_cols, so maybe we can associate that way.
SQLNumResultCols.638756.1441906535.73.tbeg ---error--- SQLNumResultCols.638756.1441906535.73.walk dump_SQLNumResultCols (fffffffe 3 22888e54) SQLNumResultCols.638756.1441906535.73.walk SQLNumResultCols (3 22888e54) SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_SQLNumResultCols_helper (?) SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_get_result_set_info (?) SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk rb_yield (?) SQLNumResultCols.638756.1441906535.73.walk int_dotimes (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_0 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk rb_yield (?) SQLNumResultCols.638756.1441906535.73.walk rb_ary_each (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_0 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk proc_call (?) SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?) SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?) SQLNumResultCols.638756.1441906535.73.walk vm_exec (?) SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?) SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?) SQLNumResultCols.638756.1441906535.73.walk thread_start_func_2 (?) SQLNumResultCols.638756.1441906535.73.walk thread_start_func_1 (?) SQLNumResultCols.638756.1441906535.73.walk _pthread_body (?) SQLNumResultCols.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3) SQLNumResultCols.638756.1441906535.73.parm SQLSMALLINT* pccol 0x22888e54 (579374676) SQLNumResultCols.638756.1441906535.73.phex 22888e54 : 000000002293fb600000002000000000 >...."..`... ....< SQLNumResultCols.638756.1441906535.73.phex 22888e64 : 000000000000000000000000205a0978 >............ Z.x< SQLNumResultCols.638756.1441906535.73.phex 22888e74 : 204aca882293fb600000002000000000 > J.."..`... ....< SQLNumResultCols.638756.1441906535.73.phex 22888e84 : 000000005b5b00000000000800000ce8 >....[[..........< SQLNumResultCols.638756.1441906535.73.phex 22888e94 : 0000316022895ee00000002000000000 >..1`".^.... ....< SQLNumResultCols.638756.1441906535.73.tend ---error---
-
Account Deleted BTW -- we are not chasing our tails, we are on to something here (hounds are barking), so figuring out what ruby script was doing when the trace entry goes bad may hold the answer. That is to say that ruby gc decided to collect our hstmt, and, appears we still wanted to use it in Ruby script (ibm_db adapater perhaps).
-
reporter but i am not sure i can synchronize/match trace log entries with rake trace. How would this be done?
They'd be two separate logs and a visual/manual review would need to be done to correlate based on epoch timestamps and method-call names. I can actually setup the TracePoint to only log when Ruby calls C. That might be the best place to start. Stay tuned.
-
reporter Observation: I don't believe I've ever experienced the column meta data error (ever) while in the
rails console
. I just tried to get the error to happen inrails console
and was unable to, yet when I go to the browser to execute more or less the same database queries it errors frequently. I've been searching for things like "Rails view multithread issues" and am not finding others with same issue.Observation: One customer I am working with is also using the Ruby xmlservice gem via the DB2 approach and the calls to RPG programs go belly up frequently. When this happens it shuts down Thin and gives this message:
Internal error in libdb400 calling SQL function SQLExecute
. I am guessing this is because the xmlservice gem is using a stale DB2 connection handle.Thought: In the past you mentioned being on a
Power5
machine. I have no idea how concurrency and parallelism has progressed as it relates to IBM i and multicore processors, but maybe that is why you can't recreate it? Note: I am on IBM i v7.2Power7
.These comments are simply to flavor our thoughts. I still plan on producing a new set of logs where we can see both the Ruby trace (mine) and paseclitrace(yours) side by side.
-
reporter First round of libdb400 + Ruby trace is complete. libdb400_trace_692348.txt and libdb400_trace_692348_ruby.txt The Ruby trace format is
class.method:lineno.epoch.ruby_thread_id
. Note theruby_thread_id
is not the operating system thread id and instead theobject_id
ofThread.current
.Below is what I added to the top of
ibm_db_adapter.rb
to produce the Ruby listing. Basically this will output to a file in/tmp
every time a method call is made toibm_db_adapter.rb
.require 'active_record/connection_adapters/abstract_adapter' require 'arel/visitors/bind_visitor' module ActiveRecord trace = TracePoint.new(:call) do |tp| if tp.path.include? 'ibm_db_adapter.rb' File.open("/tmp/libdb400_trace_#{Process.pid}_ruby","a") do |file| file.write sprintf("%s.%s:%-2d.%s.%s\n", tp.defined_class, tp.method_id, tp.lineno, Time.now.to_i, Thread.current.object_id) end end end trace.enable . . .
An Explanation
The below sequence of
active?
,reconnect!
,disconnect!
,connect
occurs hundreds of times in the log file. I believe the crazy number relates to asset (.js, .css, etc) requests which go through the full Rails request lifecycle, including readying the database for interaction, even though no interaction will take place. Something to fix another day.ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516438.303298440
Here are the API calls for a single refresh of the web page. Just good to see the call list.
Arel::Visitors::IBM_DB.visit_Arel_Nodes_SelectStatement:3785.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.quote_column_name:1863.1442516437.303298440 ActiveRecord::ConnectionAdapters::HostedDataServer.check_reserved_words:3117.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.add_limit_offset!:1715.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.query_offset_limit:2956.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.to_sql:1059.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.select:1282.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.fetch_data:1245.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.select:2217.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.columns:2067.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2_I5.columns:3326.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.columns:2540.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.serverschema:891.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516437.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.tables:1986.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.primary_key:2027.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516438.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516438.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516438.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516438.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516438.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516440.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516440.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516440.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516440.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516440.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516440.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516440.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.to_sql:1059.1442516440.303298440
I am continuing to look through the log to find other patterns.
-
Account Deleted Aaron, I tried my fancy new power 8 box, and, lateset IBM i release. Everything works fine (no missing records), aka, i can not reproduce your multiple thread error.
Oh boy, oh boy, I want your to try my version of ibm_db2 gem ... my test version ibm_db
Yes, yes, please may i be wrong about my version working ... BUT ... we really have to try this experiment. If my version works we better take this conversation off-line.
Aaron only {ibm_db test} - (2.5.14 my version) cd /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems tar -xf ibm_db-2.5.14.zip (may i be wrong … yikes)
-
reporter I am still getting the error. Here's what I did...
First I created a separate location to place the Gem:
$ mkdir -p /ruby/gemsets/ibm_db-tony/gems $ mkdir /ruby/gemsets/ibm_db-tony/specifications
FTP'd the now unzipped files to
/ruby/gemsets/ibm_db-tony/gems
. Added a line at the top ofibm_db_adapter.rb
so I can be sure I am picking up your version.$ echo "puts 'Tony version'" | cat - /ruby/gemsets/gems/ibm_db-tony/gems/ibm_db-2.5.14-powerpc-aix-6/lib/active_record/connection_adapters/ibm_db_adapter.rb > /tmp/out && mv /tmp/out /ruby/gemsets/ibm_db-tony/gems/ibm_db-2.5.14-powerpc-aix-6/lib/active_record/connection_adapters/ibm_db_adapter.rb
Need specifications file so Gem can be resolved. (Did you not have to do this?)
cp /ruby/gemsets/ibmdb_fetchbug-development/specifications/ibm_db-2.5.14-powerpc-aix-6.gemspec /ruby/gemsets/ibm_db-tony/specifications
Setup environment vars for precedence:
$ export GEM_HOME=/ruby/gemsets/ibm_db-tony $ export GEM_PATH=/ruby/gemsets/ibm_db-tony:/PowerRuby/prV2R1/lib/ruby/gems/2.1.0
Output during startup to confirm I am picking up your version:
$ rails s -p50000 /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/railties-4.1.8/lib/rails/app_rails_loader.rb:37: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777 /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:222: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777 Tony version => Booting Puma => Rails 4.1.8 application starting in development on http://0.0.0.0:50000 => Run `rails server -h` for more startup options => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option) => Ctrl-C to shutdown server Puma 2.11.1 starting... * Min threads: 0, max threads: 16 * Environment: development * Listening on tcp://0.0.0.0:50000 Started GET "/users" for 69.24.176.225 at 2015-09-21 21:59:22 +0000 (8.2ms) SET SCHEMA ab1_d (7.6ms) SET SCHEMA ab1_d ActiveRecord::SchemaMigration Load (15.4ms) SELECT schema_migrations.* FROM schema_migrations Processing by UsersController#index as HTML User Load (3.2ms) SELECT users.* FROM users Rendered users/index.html.erb within layouts/application (197.0ms) Completed 200 OK in 434ms (Views: 385.1ms | ActiveRecord: 3.2ms)
After 15 to 20 refreshes I get the follow error:
Started GET "/users" for 69.24.176.225 at 2015-09-21 21:59:55 +0000 (8.3ms) SET SCHEMA ab1_d Processing by UsersController#index as HTML User Load (16.3ms) SELECT users.* FROM users Rendered users/index.html.erb within layouts/application (35.2ms) Completed 500 Internal Server Error in 44ms ActionView::Template::Error (uncaught throw :"Column information cannot be retrieved: <error message could not be ret rieved>"): 13: </thead> 14: 15: <tbody> 16: <% @users.each do |user| %> 17: <tr> 18: <td><%= user.name %></td> 19: <td><%= user.age %></td> app/views/users/index.html.erb:16:in `_app_views_users_index_html_erb___533735991_289853340' Rendered /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb (3.3ms) Rendered /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb (21.8ms) Rendered /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/template_error.html.erb within rescues/layout (88.7ms)
Maybe
tar
up your entire/PowerRuby
folder so I can ensure I have everything the exact same as you? -
Account Deleted Ok i have download ... big ... you may need to use FTP to yips ...
Aaron only {powerruby} - (my version)
-
Account Deleted I checked big powerruby.zip download ok from wiki page.
-
reporter I've loaded the "Aaron only" version of PowerRuby into a chroot environment and am able to reproduce the issue.
I wish I could say it is unique to my particular machine but I've experienced the error on every machine I've worked on (customer's servers, AITP RubyOnRails contest servers, KrengelTech servers, QUSER.org training server, WMCPA.org training server, etc).
Possible options for next steps that I can think of:
- Tell me what traces/scenarios to try next.
- Web meeting where you watch me recreate the error and I watch you to see where our process might be different.
- I give you access to a chroot environment on my internet-facing server (no VPN required) that you can SSH into and recreate the error. I would need your
id_rsa.pub
ssh key as I've turned off ssh password authentication.
-
Account Deleted well, can we see a trace of the failing 'test', using Aaron Only PowerRuby?
aka, we already know what is wrong, garbage collector appears to be collecting a "in use" statement handle (naughty garbage collector).
-
reporter Here is the latest trace. I am actively reviewing it.
-
Account Deleted Well, same sequence ...
1) la dee da red riding hood ... ibm_db_exec -> SQLExecDirect 2) big bad wolf ... gc_finalize_deferred->SQLFreeHandle 3) scream ... ibm_db_result_cols -> SQLNumResultCols
So, it would appear that ruby Garbage Collector will not stop eating grandma #3 staetment handle ... naughty, naughty, naughty ... Mr. GC!
So, we have it coded wrong in c code, or, we need to hide our grandma statement handles/resources in closet, away resources from big bad wolf Mr GC.
SQLExecDirect.726139.1442947138.1.tbeg +++success+++ SQLExecDirect.726139.1442947138.1.walk dump_SQLExecDirect (0 3 23234bd0 1a) SQLExecDirect.726139.1442947138.1.walk SQLExecDirect (3 23234bd0 1a) SQLExecDirect.726139.1442947138.1.walk _ruby_ibm_db_SQLExecDirect_helper (?) SQLExecDirect.726139.1442947138.1.walk ibm_db_exec (?) SQLFreeHandle.726139.1442947138.1.tbeg +++success+++ SQLFreeHandle.726139.1442947138.1.walk dump_SQLFreeHandle (0 30003 3) SQLFreeHandle.726139.1442947138.1.walk SQLFreeHandle (30003 3) SQLFreeHandle.726139.1442947138.1.walk _ruby_ibm_db_free_stmt_struct (?) SQLFreeHandle.726139.1442947138.1.walk finalize_list (?) SQLFreeHandle.726139.1442947138.1.walk gc_finalize_deferred (?) SQLFreeHandle.726139.1442947138.1.walk rb_postponed_job_flush (?) SQLFreeHandle.726139.1442947138.1.walk rb_threadptr_execute_interrupts.part.37 (?) SQLFreeHandle.726139.1442947138.1.walk vm_exec_core (?) SQLFreeHandle.726139.1442947138.1.walk vm_exec (?) SQLNumResultCols.726139.1442947138.1.tbeg ---error--- SQLNumResultCols.726139.1442947138.1.walk dump_SQLNumResultCols (fffffffe 3 212b25b4) SQLNumResultCols.726139.1442947138.1.walk SQLNumResultCols (3 212b25b4) SQLNumResultCols.726139.1442947138.1.walk _ruby_ibm_db_SQLNumResultCols_helper (?) SQLNumResultCols.726139.1442947138.1.walk _ruby_ibm_db_get_result_set_info (?) SQLNumResultCols.726139.1442947138.1.walk ibm_db_result_cols (?)
-
Account Deleted The other possibility was that the ruby script code (ibm db adapter), has scope of the statement incorrectly designed. That is, #3 statement goes out of scope between ibm_db_exec and ibm_db_result_cols ... but ... you are already working on a converged trace to help us understand what the bloody ruby code was doing at the time of #3 statement death-by-garbage-collector.
-
Account Deleted Are you understanding all of this feedback?? And, do you believe what i am saying???
-
reporter So, we have it coded wrong in c code,
And by that are you talking about the Ruby c code or ibm_db.c? The latter we can affect within this code base. The former we'd need to engage the PowerRuby team.
Also, should we convey our findings to the LUW ibm_db group (this issue)? I am wondering if they'd know right where to fix this or maybe they already have.
-
reporter Are you understanding all of this feedback?? And, do you believe what i am saying???
The latest results had one thread (from what I could see) so that causes me to lean towards Mr. GC being the issue. So yes, I agree with the current direction.
but ... you are already working on a converged trace to help us understand what the bloody ruby code was doing at the time of #3 statement death-by-garbage-collector.
I did produce two traces in this post (one paseclitrace and the other Ruby) from late last week but you didn't comment on it so I don't know if it was useful. Maybe TL;DR? Do you want me to run it again with the PowerRuby version you gave me?
-
Account Deleted Mmm ... sorry, doing many things at same time ... i have not yet figured out how to merge two trace files, are you working on a tool to 'merge' into one file (i thought your were)???
-
reporter i have not yet figured out how to merge two trace files, are you working on a tool to 'merge' into one file (i thought your were)???
I can, yes, but I originally asked for clarity to make sure I was going to produce what you envisioned/needed. Your above comment gives me direction (you want the two files merged and not just queried/searched).
Below is an example I manually copy/pasted where entries from paseclitrace and Ruby trace are sorted by timestamp. Is that basically what you are looking for?
SQLOverrideCCSID400.692348.1442516426.1.tbeg +++success+++ SQLOverrideCCSID400.692348.1442516426.1.walk dump_SQLOverrideCCSID400 (0 4b8) SQLOverrideCCSID400.692348.1442516426.1.walk SQLOverrideCCSID400 (4b8) SQLOverrideCCSID400.692348.1442516426.1.walk _ruby_ibm_db_SQLOverrideCCSID400_helper (?) SQLOverrideCCSID400.692348.1442516426.1.walk ruby_init_ibm_db (?) SQLOverrideCCSID400.692348.1442516426.1.walk Init_ibm_db (?) SQLOverrideCCSID400.692348.1442516426.1.walk dln_load (?) SQLOverrideCCSID400.692348.1442516426.1.walk load_ext (?) SQLOverrideCCSID400.692348.1442516426.1.walk rb_vm_call_cfunc (?) SQLOverrideCCSID400.692348.1442516426.1.walk rb_require_safe (?) #<Class:ActiveRecord::Base>.ibm_db_connection:290.1442516436.303298440 ActiveRecord::ConnectionAdapters::TableDefinition.initialize:720.1442516427.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.initialize:899.1442516427.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2_I5.initialize:3240.1442516427.303298440 ActiveRecord::ConnectionAdapters::IBM_DB2.initialize:2630.1442516427.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.initialize:2178.1442516427.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516427.303298440 ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516427.303298440 ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516427.303298440
-
Account Deleted ok, but what was happening around the actual error ...
1) where was ruby script here ... SQLExecDirect.726139.1442947138.1.tbeg +++success+++ 2) where was ruby script here ... (this one you may not find) SQLFreeHandle.726139.1442947138.1.tbeg +++success+++ 3) where was ruby script here ... SQLNumResultCols.726139.1442947138.1.tbeg ---error---
-
Account Deleted As far a c-code, i doubt LUW will have any idea what you are talking about, although, i thought you said they were also experiencing issue on Linux. Anyway, We/You/Me have CLI trace with walk back to actually see GC interrupt the ruby script to process the garbage. LUW has nothing even close to this level of details (just so you understand how good this trace is actually).
The steps ...
... after we eliminate ruby ibm_db adapter scope, aka, find merged two trace to identify locations when SQLNumResultCols occurred
... then we decide if it looks like c code error (it does look like bad c code not so far).
... last, we fix either the ruby code or the c code (perhaps need to hack away from ruby GC)
-
reporter Merge program is complete and I have a first round for us to look at.
##Files - libdb400_trace_727067_merged_sorted.txt <--- What we are currently interested in - libdb400_trace_727067.txt - libdb400_trace_727067_ruby.txt
Note libdb400_trace_727067_merged_sorted.txt has junk lines in the beginning because some of the libdb400 trace lines don't include the API name and cut the epoch in the middle (see below for example).
SQLNumResultCols.727067.1442970011.1.tend +++success+++ 2970011.1.walk vm_call0_body.constprop.63 (?) <-----this one is missing API and portion of epoch SQLDescribeCol.727067.1442970011.1.walk rb_call0 (?)
ibm_db_adapter.rb insertion
Below is how I am collecting all method calls occurring in
ibm_db_adapter.rb
. Note: I could go beyond:call
event notifications if we need it (based on Ruby TracePoint docs).require 'active_record/connection_adapters/abstract_adapter' require 'arel/visitors/bind_visitor' module ActiveRecord trace = TracePoint.new(:call) do |tp| if tp.path.include? 'ibm_db_adapter.rb' File.open("/tmp/libdb400_trace_#{Process.pid}_ruby","a") do |file| file.write sprintf("%s.%s:%-2d.%s.%s\n", tp.defined_class, tp.method_id, tp.lineno, Time.now.to_i, Thread.current.object_id) end end end trace.enable
##Merge Program This is the merge program. I put the epoch and iterator at the beginning of each line so the subsequent
sort
would succeed.# $ ruby trace_merge.rb /tmp/libdb400_trace_727067 /tmp/libdb400_trace_727067_ruby /tmp/libdb400_trace_727067_merged.txt File.open(ARGV[2], "w") do |merged_file| [ARGV[0], ARGV[1]].each do |in_file| i = 1 IO.foreach(in_file) do |line| key = line.split '.' str = "file_" + i.to_s.rjust(7, "0") merged_file.puts(key[2] + "-#{i.to_s.rjust(7, "0")}---" + line) rescue merged_file.puts('ZZ unable to split line---' + line) i += 1 end end end
##Sort
$ sort /tmp/libdb400_trace_727067_merged.txt > /tmp/libdb400_trace_727067_merged_sorted.txt
-
Account Deleted Mmm ... seems like a lot of work ... maybe i could just provide you a new call in libdb400.a like SQLAddMyTraceData(string), thereby, all the time/thread/key data would be "auto magically" taken care. We just a 'internal dynamic' function _db2_add_trace(string) to ibm_db2.c, and, if libdb400.a exported the signature, you can simply call it. What do you think???
-
reporter seems like a lot of work ...
I digressed into details for historical purposes. In the end you only need to look at this file to see when Ruby/SQL CLI events occur. With that said...
maybe i could just provide you a new call in libdb400.a like SQLAddMyTraceData(string), thereby, all the time/thread/key data would be "auto magically" taken care.
Yes, that would be perfect.
-
Account Deleted Nuts, i can't make heads or tails out of the merged list, i think you need to use something other than "walk" in your key, aka, c code says walk, ruby code says "run" or something like that. Anyway per previous, this whole idea trace in ruby may be better via a db2_add_trace(string) function, and, let the libdb400.a trace module deal with "merge".
What do you think?
-
reporter Anyway per previous, this whole idea trace in ruby may be better via a db2_add_trace(string) function, and, let the libdb400.a trace module deal with "merge". What do you think?
Yes, that would be a good direction.
-
Account Deleted BTW -- just so i do not forget, we may have to make use of RB_GC_GUARD in the ibm_db c code (hide from ruby GC), some comments about Ruby GC in relation to compiler optimizations. ruby gc
-
reporter Am I correct to understand from that article we will be using
RB_GC_GUARD
on SQL CLI handles?Unsure if related but Ruby has a concept of "copy on write" for parameters. This guy digresses through it nicely.
-
Account Deleted Yes, "guard" SQL handles. However, our mixed trace has not yet eliminated a simple 'scope of statement' error in ruby script side (yet). But, mmm, leaning, ahh, leaning, toward using the guard, because eveidence both on IBM i and other LUW dealing with Ruby GC..
.... but, but, but, relatively sophisticated article points out, we should NEVER have to 'guard' against a design 'error'. Aka, depending on which PHD talking, Ruby guys messed up over engineering for performance sake (common problem for garbage collecting in any language).
-
Account Deleted BTW -- interesting,brings to mind a Clint Eastwood movie ...
Good -- advertising greatness of Ruby CG design good
Bad -- proclaiming terrible Ruby GC design bad
Ugly -- well, we seem to clearly be having problems with Ruby GC jumping in and destroying our 'in use' handles. Not only IBM i, but on LUW ibm_db in other messages ...
We all see the world as we wish i guess ... but ... we still need the mixed trace data.
-
reporter #"Don't die, I'll get you water. Stay there. Don't move, I'll get you water. Don't die until later." - Tuco
Looking forward to the mixed trace data API. Will implement it asap.
-
Account Deleted Sorry, i was pointing he finger to me on the trace ... i need to add a new feature db2_add_trace(string) function, may not give us all we need, but could help eliminate easier ruby script issues as they come up.
Btw -- again, i am most interested in giving YOU the ability to work issues with confidence. In the end, if this is a ruby GC design, we probably will simply 'guard' our way out of the maze ... and ... while the trace was useful to detect the issue, it still left subjective understanding to the authors of the c code (you and me). Therein, we would need to work together on a crazy animal like this as it sits on the edge of PHDs arguing above all listening.
-
reporter i am most interested in giving YOU the ability to work issues with confidence.
I am getting more confident in how to debug and what the parts of the traces are conveying, but it's knowing
gc_finalize_deferred
are red flags is where I lack. I suppose that will have to come with time. I will eventually be writing articles about this lower-level debugging stuff but I needed to get all the "intro to xxxx" stuff done first so people are actually using this open source/PASE. -
Account Deleted Off topic (not part of issue), your question about "copy on write" ...
"The speed" of forked process Linux/AIX/PASE are build on "copy on write" principle. That is to say, when a parent process/job forks a child process it still has exact memory image of the parent, BUT, any changes (writes) child makes to any memory results in a "copy on write" "page". You can think of parent process freezing it's memory image at fork time (except to itself -- parent only write), wherein child only allowed to read, and, if child changes he gets his own 'alias' copy of the memory to replace the frozen parent memory. Needless to say, this is a VERY efficient model, in that, a child job that does not 'exec' (run new program), will likely leave a high percentage of the memory untouched.
Similar topic, using same "copy on write" idea, kernel program loaders of Linux/AIX/PASE load shared stuff (libthing.a and thing.so) into kernel parent memory image for text/code and data. where, shared is defined by file system other *RX bits, on shared thing.so, aka, none shared loads from scratch into process private memory. Anyway, assuming shared (90% case), new process started form anywhere on the machine inherits the pre-resolved image of the library tree (dependencies), and, like our fork mechanics, changes to data parts of the shared library memory (variables inside the thing.so), form "copy on write" chunks in the new process.
The article ...
Possibly this server is running Apache with something like Passenger that forks a separate Ruby process to handle each HTTP request.
well, mmm, cough, we all know Ruby/Rails MOST applications are pre-start daemon and thread oriented, therefore NEVER spawn/fork new processes to handle work ... so ... gee ... "copy on write" for process ... gee ... well even FAstCGI spawns then keeps active .. so .. gee ... mmm ... what is the nice way to say "who cares"??
-
Account Deleted Ok, i have a merged trace ...
module ActiveRecord ############################# # trace -- (Aaron) ############################# trace = TracePoint.new(:call) do |tp| if tp.path.include? 'ibm_db_adapter.rb' IBM_DB.trace(sprintf("%s %s %-2d", tp.defined_class, tp.method_id, tp.lineno)) end end trace.enable
... but ... creates a lot of data ...
SQLFreeHandle.40907.1443477662.3.tend +++success+++ script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBColumn type_cast 578 script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBColumn type_cast 578 script.40907.1443477662.3.run hey adc i am in welcome controller script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBAdapter quote_column_name 1821 script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::HostedDataServer check_reserved_words 3075 script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBAdapter tables 1944 script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DB2 set_case 3012 SQLAllocHandle.40907.1443477662.3.tbeg +++success+++ SQLAllocHandle.40907.1443477662.3.walk dump_SQLAllocHandle (0 30003 2 2301fa14) SQLAllocHandle.40907.1443477662.3.walk SQLAllocHandle (30003 2 2301fa14)
So, i am thinking options for script paseclitrace.ini ... or ... maybe something in ruby trace (see trace Aaron in ibm_db_adapter.rb above) ...
have any ideas???
-
reporter So, i am thinking options for script paseclitrace.ini ... or ... maybe something in ruby trace (see trace Aaron in ibm_db_adapter.rb above) ...
How about a generic
lang_trace_type
option:; lang_trace_type ; 0 - trace all ; 1 - trace warnings ; 2 - trace errors only lang_trace_type=0
Then we can use this for Node.js, Python, Scala, etc. Each language/programmer will be responsible for implementing their concept of what levels 0,1,2 mean (or they could ignore them completely).
Could you put the new trace on YiPs?
-
Account Deleted No, unfortunately is chicken and egg for the script. That is to say ruby 'script code' does not know there will be an error until after call to CLI driver libdb400.a (c code), and, has already logged "i am here in my script".
So i am beginning to think we will have to offer some sort of secondary calls ...
# 1) default trace everything, but exclude where these strings appear IBM_DB.trace_exclude('type_cast','simplified_type', ...) -- or -- # 2) default trace nothing, but include only where these strings appear IBM_DB.trace_include('execute','fetch_data', ...)
-
Account Deleted However, i like additional control idea enable off/on script tracing ...
; script_trace_type ; 0 - script off ; 1 - script on script_trace_type=1
-
reporter Could
trace_exclude
andtrace_include
accept a regex so it is configurable in a single parameter with better matching capabilities?Thumbs up on
script_trace_type
and corresponding options. -
Account Deleted No regex (i knew you would ask). Trace version of libdb400.a is a simple c program, from a simple man (me), no dependencies on anything esoteric like "regex", aka, i will not sign-up to build and/or make a dependency on a library IBM does not ship. No, this will be a simple strcmp of the array elements appear in the list (yes/no).
-
reporter i will not sign-up to build and/or make a dependency on a library IBM does not ship.
Does IBM intend to ship this trace utility with IBM i?
-
Account Deleted No. In fact, probably another Open Source project for us.
However, perhaps leads to IBM PTF in future, IF/when people start to understand what this new feature offers.
BTW -- I am a true believer in open source model, try it out, if good, keep it active in the community. Yes, our community is small (me/you), but every tree starts from a seed.
-
Account Deleted Ok, I have new ibm_db gem source that included RUBY_GC_GUARD (*). I tested and works fine on my machine, but, well, i never had the problem. So i guess test falls to you and your machine. ibm_db gem source
I have a new libdb400.a 1.0.6 trace enables merged log files using IBM_DB.trace("msg"), etc. libdb400.a 1.0.6
(*) Note: Assuming all goes well with your test ... I can NOT legally post a pre-compiled ibm_db gem as 'IBM' (i don't believe). Can you volunteer for 'build role' for others that need ibm_db gem update??? ... other ideas???
-
reporter What approach are you using to compile this gem? I am reviewing zzall_ibm_i.sh and see that the
gem compile
line is commented out. I believegem compile
is meant to use thegem-compiler
Gem. Just want to make sure I am approaching it the same way.Can you volunteer for 'build role' for others that need ibm_db gem update???
Yes, I can play the build role.
-
Account Deleted i use zzall_ibm_i.sh "as is" with xlc compiler and everything works for me, perhaps gem compile is implicit step apparently during gem install.
-
Account Deleted Oh boy, I am using the gcc compiler with zzall_ibm_i.sh (not xlc). I am soooo sorry if i made you chase a xlc compiler download. Here is the compiler i am using.
bash-4.3$ gcc --version gcc (GCC) 4.8.3 Copyright (C) 2013 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
-
Account Deleted If you want you can set-up via perzl chroot and/or pkg 4.8.3 in our GCC chroot project. Again, apologies about xlc, i am using gcc for Ruby gems.
-
reporter Been at nhmug.org preaching about Node.js and Git all of yesterday. In transit right now and hope to run a build this afternoon.
-
reporter Ok, silly question, but what do I need to install to get include file
sqlcli1.h
?% gem install ./ibm_db-2.5.15.pre.beta.gem --local --force --ignore-dependencies --no-rdoc Building native extensions. This could take a while... /PowerRuby/prV2R1/lib/ruby/site_ruby/2.1.0/rubygems/ext/builder.rb:73: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777 ERROR: Error installing ./ibm_db-2.5.15.pre.beta.gem: ERROR: Failed to build gem native extension. /PowerRuby/prV2R1/bin/ruby -r ./siteconf20151002-751915-1r2ci0q.rb extconf.rb extconf.rb:13: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777 Detected 32-bit Ruby compile type 3) Ruby >= 1.9 IBM i PASE_RELEASE_VERSION extconf.rb:134: warning: already initialized constant IBM_DB_HOME extconf.rb:28: warning: previous definition of IBM_DB_HOME was here creating gil_release_version creating unicode_support_version checking for gil_release_version... yes checking for unicode_support_version... yes creating Makefile make "DESTDIR=" clean make "DESTDIR=" compiling ibm_db.c In file included from ruby_ibm_db_cli.h:20:0, from ruby_ibm_db.h:17, from ibm_db.c:32: ruby_sql_com.h:80:61: fatal error: sqlcli1.h: No such file or directory #include <sqlcli1.h> /* include top for overrided to work */
-
Account Deleted In gem, I included zzcopyincludes_ibm_i.sh shell script to copy CLI includes from ILE to PASE.
$ cat zzcopyincludes_ibm_i.sh #!/QOpenSys/usr/bin/ksh ls /QIBM/include/sql* > ./list2 for i in $(< ./list2) do echo "PREPARATION COPY" system -v "CPY OBJ('$i') TODIR('/usr/include/') TOCCSID(*STDASCII) DTAFMT(*TEXT) REPLACE(*YES)" done rm list2
However, LUW uses sqlcli1.h (everywhere), so please add that include to PASE as follows.
bash-4.3$ cat /usr/include/sqlcli1.h #include "sql.h" #include "sqlca.h" #include "sqlcli.h"
-
reporter Good news: I am now successfully compiling the gem.
Bad news: I am still getting the error. Here is the new combined log using the latest gem and tracing.
-
Account Deleted Disappointing, same sequence of bad Ruby GC behaviour. Well, we will have to take stronger measures to keep our active statements away from the snarling teeth of the Ruby GC ... bad gc dog, bad gc dog!!
===== RUBY CG double deletes nearly all the time ==== SQLFreeHandle.752347.1443822136.13.walk gc_finalize_deferred (?) SQLFreeHandle.752347.1443822136.13.walk gc_finalize_deferred (?) SQLFreeHandle.752347.1443822136.13.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) ==== same sequence Ruby CG delete active statement ======== SQLFreeHandle.752347.1443822262.105.tbeg +++success+++ SQLFreeHandle.752347.1443822262.105.walk dump_SQLFreeHandle (0 30003 3) SQLFreeHandle.752347.1443822262.105.walk SQLFreeHandle (30003 3) SQLFreeHandle.752347.1443822262.105.walk _ruby_ibm_db_free_stmt_struct (?) SQLFreeHandle.752347.1443822262.105.walk finalize_list (?) SQLFreeHandle.752347.1443822262.105.walk gc_finalize_deferred (?) : SQLFreeHandle.752347.1443822262.105.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS SQLFreeHandle.752347.1443822262.105.parm SQLSMALLINT htype 0x3 (3) SQLFreeHandle.752347.1443822262.105.parm SQLINTEGER hndl 0x3 (3) SQLFreeHandle.752347.1443822262.105.tend +++success+++ SQLNumResultCols.752347.1443822262.105.tbeg ---error--- SQLNumResultCols.752347.1443822262.105.walk dump_SQLNumResultCols (fffffffe 3 21ac6934) SQLNumResultCols.752347.1443822262.105.walk SQLNumResultCols (3 21ac6934) SQLNumResultCols.752347.1443822262.105.walk _ruby_ibm_db_SQLNumResultCols_helper (?) SQLNumResultCols.752347.1443822262.105.walk _ruby_ibm_db_get_result_set_info (?) SQLNumResultCols.752347.1443822262.105.walk ibm_db_result_cols (?) : SQLNumResultCols.752347.1443822262.105.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLNumResultCols.752347.1443822262.105.parm SQLHSTMT hstmt 0x3 (3) SQLNumResultCols.752347.1443822262.105.parm SQLSMALLINT* pccol 0x21ac6934 (564947252) SQLNumResultCols.752347.1443822262.105.phex 21ac6934 : 0000000021ac6ac00000002000000000 >....!.j.... ....< SQLNumResultCols.752347.1443822262.105.phex 21ac6944 : 000000000000000000000000205a0978 >............ Z.x< SQLNumResultCols.752347.1443822262.105.phex 21ac6954 : 0000000021ac6ac00000002000000000 >....!.j.... ....< SQLNumResultCols.752347.1443822262.105.phex 21ac6964 : 000000005b5b00000000001a64622f6d >....[[......db/m< SQLNumResultCols.752347.1443822262.105.phex 21ac6974 : 6967726174652f2a2a2f5b302d395d2a >igrate/**/[0-9]*< SQLNumResultCols.752347.1443822262.105.tend ---error---
-
Account Deleted Aaron, Ok, i have temporarily removed Ruby GC from collecting statement handles (i think). Please give this new version a try and see if the issue disappears.
--- this is where ruby GC is notified ok to mark, free our statement handles --- _ruby_ibm_db_mark_stmt_struct, _ruby_ibm_db_free_stmt_struct, stmt_res); RB_GC_GUARD(return_value); --- this is where ruby CG actually frees our handles, and, i commented out the delete (for now/test) --- /* static _ruby_ibm_db_free_stmt_struct */ static void _ruby_ibm_db_free_stmt_struct(stmt_handle *handle) { /* ADC -- fix this after test. if ( handle != NULL ) { _ruby_ibm_db_free_stmt_handle_and_resources( handle ); ruby_xfree( handle ); handle = NULL; } */ }
-
Account Deleted Sorry, my cut paste did not grab the whole statement for your to see the mark, free wrap ...
return_value = Data_Wrap_Struct(le_stmt_struct, _ruby_ibm_db_mark_stmt_struct, _ruby_ibm_db_free_stmt_struct, stmt_res); RB_GC_GUARD(return_value);
-
reporter #Good news!
I was not able to produce the error after 20 minutes of refreshing. Below is the only reference to an error in file/tmp/libdb...
:% grep -i 'error' /tmp/libdb400_trace_15287 SQLGetFunctions.15287.1444341763.6.tbeg ---error--- SQLGetFunctions.15287.1444341763.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR) SQLGetFunctions.15287.1444341763.6.tend ---error--- SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..< SQLBindCol.15287.1444342179.248.phex 2322a310 : 7265736f757263655f6572726f727300 >resource_errors.<
Are there other steps we need to take at this point other than compile a version for distribution? I'd like to put this on RubyGems.org like we did for xmlservice. That way people can get access to our latest work. As we discussed, I will do the compile/distribution vs. you.
-
reporter Did you want to see the trace? It is 200MB + in size.
-
Account Deleted Well, this was only a test version. That is we neutered statement handle free. We should be more judicious, cleanly, avoid running out of statement handles in final fix.
I do not want to see 200MB trace, aka, our new trace works too good, perhaps cut/paste 10-20 calls around the error notification, just to look into the box.
-
reporter -
Account Deleted Completely benign ... our new 'merged trace', uses unsupported function in SQLGetFunctions 0x3e7 == 999, which is used to decide if we can add script trace data at all. SQLOverrideCCSID400 occurs before the SQL environment is even set, chicken/egg issue that will happen each time started, we will have to look at not asking the question on this API (probably only SQLOverrideCCSID400).
-
Account Deleted Ok, i think you can release this fix "as is". I looked at the ibm_db.c code, and, the customer is able to free statements returned as resources on his own. However, if the customer does not free returned statement handles, well, tough luck, aka, no good place to "baby sit" bad applications, especially Rails applications, because they intentionally hold db2 connection open forever (even if open same profile more than once ... stupid).
Second, it appears you may be using an older version of the trace libdb400.a, please upgrade from the Yips site, then retry to see if SQLGetFunctions invalid handle goes away.
-
reporter Second, it appears you may be using an older version of the trace libdb400.a
Here is the version I am using and how I prime my shell session before starting the Rails app. It appears I am using the most current version according to what I see on YiPs. Let me know if you'd like me to try something else.
export LIBPATH=/QOpenSys/download/trace-1.0.6-xlc export PASETRACE=/QOpenSys/download/trace-1.0.6-xlc/paseclitrace.ini export IBM_DB_GIL="00000000000000000000000000000000000000000000"
Ok, i think you can release this fix "as is".
Will do. I'd like to run a couple of enhancements past you to get your agreement.
- 1) Move all files in
ruby-ibm_db/IBM_DB_Adapter/ibm_db/
up to top of project. I will usegit mv
so we retain file history. - 2) Go down to one README* file. I will work through them and come up with a single one that addresses our needs.
- 3) Remove prior version
*.gemspec
files and resort to the singleibm_db.gemspec
(which currently exists). Previous versions exist in commit history so we lose nothing. - 4) Publish to rubygems.org as version ibm_db-2.5.15
On final note, Andrea or PowerRuby, is there anything in here that would keep you from including this version in the PowerRuby Community Edition distribution?
- 1) Move all files in
-
Account Deleted 1-4) I see no functional reason to change git geometry (move things around). Why take the chance of breaking something just for "pretty". So, no, leave it alone.
I am not sure about the one error in trace libdb400.a. However, i want to make VERY clear that trace version libdb400.a is NOT to be used in production, or shipped with ibm_db ruby gem. Trace version of libdb400.a is for debug ONLY, there is no dependencies on our fix to ibm_db.
I don't think you need IBM_DB_GIL. In fact you should re-test without this setting to assure the Ruby GC fix is good.
-
Account Deleted Maybe one extra note for clarity, as mentioned, you need to re-test without trace libdb400.a, and, NO "export" settings (nothing). We need to make sure normal production path has fixed Ruby GC problem.
-
Account Deleted One more thing, leave the version alone. IBM legal thing, fixes are ok, new version is a legal review, aka, another legal review if we change the ibm_db version. Argh, just, just, just, don't ask.
-
reporter I see no functional reason to change git geometry (move things around). Why take the chance of breaking something just for "pretty". So, no, leave it alone.
It was more an effort to follow convention and give clarity, which are both important for community involvement. I will leave it alone.
However, i want to make VERY clear that trace version libdb400.a is NOT to be used in production, or shipped with ibm_db ruby gem.
Agreed.
I don't think you need IBM_DB_GIL. In fact you should re-test without this setting to assure the Ruby GC fix is good.
The past number of recent tests I've first produced the error without trace, and then once the error was produced I turned on trace to reproduce it. Regardless, I will do another round without trace/exports before packaging it up.
One more thing, leave the version alone. IBM legal thing, fixes are ok, new version is a legal review, aka, another legal review if we change the ibm_db version. Argh, just, just, just, don't ask.
Gem versions are how an app differentiates what is used (i.e. specify higher version in
Gemfile
). By not changing the version the probability of accidental usage of old gem goes up. I thought me producing the deliverable addressed this issue. -
Account Deleted Yes and no, i understand gem version reasons, service and all, but no we can not change the version, or, i really do have to do another review of source code with IBM legal (representative). Oh man, please do not ask any more, i am embarrassed by this cooperate process ...
-
reporter Once ibm_db is compiled where are we allowed to put it for distribution? Without being able to differentiate versions I am hesitant to put it on RubyGems.org. Thoughts on putting it in this project's downloads section?
Andrea, are you still monitoring this thread? Does having the same version affect whether PowerRuby includes this iteration in the distribution?
-
Account Deleted Once you (not i), compile the source to make the gem, you (not i), can do whatever you want with it.
However, opinion, if you IBM i currently have version of ruby gem ibm_db, i would simply blast over the old version RubyGems.org. To wit, who cares? Akak, someone has a problem, go install the latest from RubyGems.org, easy as pie.
BTW -- I have no intention of going back to IBM legal review for a new version every ten lines of code (actually this fix removed ten lines of code).
-
reporter Akak, someone has a problem, go install the latest from RubyGems.org, easy as pie.
And that's the issue, if we don't change the version then when someone runs
bundle install
it will think it already has the right version and not pull the latest. They'd have to do manual installation and I can't imagine that going well for shops that are new(er) to Ruby. Which in turn will have people coming to us asking for support.you (not i), can do whatever you want with it.
Wouldn't that also include publishing to RubyGems.org with the version of my choice? I figure as long as I leave you/IBM out of the process then I am acting entirely on my own and not causing you/IBM liability. Right? I am pushing for this because it is better for the community (and for saving me time).
-
Account Deleted Sorry, no, once you ship a different version of the source, then i have to go back to the IBM legal review. This is why i hesitated to make a fork git account for ibm_db at all. In this case IBM 'approvers' are ok with a version of ibm_db, same as LUW, and ok with 'reasonable' fixes to source version.
Really, simply a fact of working for IBM ... and ... within IBM OS contribution process. I do not make the IBM OS legal rules, i simply follow the rules.
So, we had better think of a way to update ibm_db gem without creating a new version.
-
Account Deleted BTW -- if you wish to disagree with IBM OS processes, and, version review rules, you need to talk to a IBM vice president. I, Ranger 'Nobody', have no influence on matters of state (obviously).
-
reporter I doubt I could change the mind of a VP either, so I will pass.
#Distribution Next steps (documenting the how of distribution)...
To distribute a gem that doesn't need to be compiled by others I need to make it into a "fat binary gem". To accomplish this I needed to install gem-compiler and then run the following command:
$ gem compile ibm_db-2.5.14.gem
Which produces a file named
ibmi_db-2.5.14-powerpc-aix-6.gem
(now we know where PowerRuby naming comes from).I then uploaded it to this project's download page.
A user can do
wget https://bitbucket.org/litmis/ruby-ibm_db/downloads/ibm_db-2.5.14-powerpc-aix-6.gem
and thengem install ./ibm_db-2.5.14-powerpc-aix-6.gem
.#Future updates We can continue to keep the version/file named the same and differentiate "fixes" via other means (i.e. a fix.txt file or something - your call).
Thoughts?
-
reporter Scratch
wget
(doesn't work with SSL, silly).curl -OkL https://bitbucket.org/litmis/ruby-ibm_db/downloads/ibm_db-2.5.14-powerpc-aix-6.gem
-
reporter I attempted to install the compiled gem on a machine that only has prV2R0 and it bombed with the following. I then tried rebuilding the gem with prV2R0 in my
PATH
but that gave the same result.$ rails s -p11030 /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/app_rails_loader.rb:37: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777 /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:222: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777 /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.rb:1:in `require': load failed - /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so. Please issue below command for detailed reasons: (LoadError) /usr/sbin/execerror ruby "30 /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so" "36 ___strcmp 1 /usr/lib/libc.a shr.o" "36 ___strcpy 4 /usr/lib/libc.a shr.o" "2 /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so" "6 8" from /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.rb:1:in `<top (required)>' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:76:in `require' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:76:in `block (2 levels) in require' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:72:in `each' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:72:in `block in require' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:61:in `each' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:61:in `require' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler.rb:133:in `require' from /home/aaron/git/myapp/config/application.rb:7:in `<top (required)>' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:74:in `require' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:74:in `block in <top (required)>' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:71:in `tap' from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:71:in `<top (required)>' from bin/rails:4:in `require' from bin/rails:4:in `<main>' <bc.a shr.o" "2 /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so" "6 8" Could not load program ruby: Symbol resolution failed for /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so because: Symbol ___strcmp (number 1) is not exported from dependent module /usr/lib/libc.a(shr.o). Symbol ___strcpy (number 4) is not exported from dependent module /usr/lib/libc.a(shr.o). Could not load module /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so. System error: Exec format error Examine .loader section symbols with the 'dump -Tv' command.
The following produces no results so I am guessing PowerRuby uses the
libc.a
shipped with PASE:$ find /PowerRuby -name 'libc.a' $
Any idea on how to fix this?
-
Account Deleted You need to compile the gem with OLDEST possible supported PASE for PowerRuby. I believe PoweRuby runs on V7R1+, so compile your gem on V7R1 machine (and use on all releases IBM i).
-
Account Deleted Here ...
This is my V7R2 machine ... ok for your gem ...
bash-3.00$ dump -Tuv /usr/lib/libc.a | grep ___strcpy [474] 0x0000fc00 undef ImpExp XO EXTref [noIMid] ___strcpy
From my V7R1 machine ... not work gem ...
$ dump -Tuv /usr/lib/libc.a | grep ___strcpy $
-
reporter You need to compile the gem with OLDEST possible supported PASE for PowerRuby. I believe PoweRuby runs on V7R1+, so compile your gem on V7R1 machine (and use on all releases IBM i).
That was the issue. I have produced a new gem file and will replace the existing one in the downloads section.
-
reporter - changed status to resolved
I am marking this as resolved. I have installed the fix into multiple applications and it has worked successfully.
- Log in to comment
I have lost track of release your machine, but i think please install PTF SI57578 to fix for 32bit dbx. Then we can continue with debug.