[elephant-devel] Problem with transactions

[Waldo Rubinstein]

I'm testing the with-transaction macro bulk loading custom classes  
into elephant and encountered a little snag.

I'm initially loading about 300 objects in the database. The  
performance using with-transaction as opposed to not using it  
(meaning committing after each object is "written") is significant.  
See below:

** not using with-transaction:
CL-USER> (time (oonet:load-834-tape "01053rdSupp.EDI"))
(COM.OONET.EDI:LOAD-834-TAPE "01053rdSupp.EDI") took 2,341  
milliseconds (2.341 seconds) to run.
Of that, 487 milliseconds (0.487 seconds) were spent in user mode
          422 milliseconds (0.422 seconds) were spent in system mode
          1,432 milliseconds (1.432 seconds) were spent executing  
other OS processes.
309,800 bytes of memory allocated.

** using with-transaction:
CL-USER> (time (oonet:load-834-tape "01053rdSupp.EDI"))
(COM.OONET.EDI:LOAD-834-TAPE "01053rdSupp.EDI") took 624 milliseconds  
(0.624 seconds) to run.
Of that, 270 milliseconds (0.270 seconds) were spent in user mode
          19 milliseconds (0.019 seconds) were spent in system mode
          335 milliseconds (0.335 seconds) were spent executing other  
OS processes.
314,160 bytes of memory allocated.

It seems to be approximately 4 times faster using with-transaction,  
which makes sense.

When I try loading a larger set of objects (approximately 13,000),  
the program works as follows:

** not using with-transaction:
CL-USER> (time (oonet:load-834-tape "0106.EDI"))
(COM.OONET.EDI:LOAD-834-TAPE "0106.EDI") took 480,914 milliseconds  
(480.914 seconds) to run.
Of that, 118,046 milliseconds (118.046 seconds) were spent in user mode
          101,881 milliseconds (101.881 seconds) were spent in system  
mode
          260,987 milliseconds (260.987 seconds) were spent executing  
other OS processes.
301 milliseconds (0.301 seconds) was spent in GC.
66,954,792 bytes of memory allocated.

** using with-transaction:
CL-USER> (time (oonet:load-834-tape "RDTLMCNA0106.EDI"))
Berkeley DB error: Cannot allocate memory
    [Condition of type SLEEPYCAT:DB-ERROR]

Restarts:
   0: [ABORT-REQUEST] Abort handling SLIME request.
   1: [ABORT-BREAK] Reset this process
   2: [ABORT] Kill this process

Backtrace:
   0: (#<STANDARD-METHOD SLOT-BOUNDP-USING-CLASS :AROUND  
(ELEPHANT:PERSISTENT-METACLASS ELEPHANT:PERSISTENT-OBJECT  
ELEPHANT::PERSISTENT-SLOT-DEFINITION)> #<ELEPHANT:PERSISTENT- 
METACLASS COM.OONET.EDI:834-ENTRY> #<PERSISTENT-EFFECTIVE-SLOT- 
DEFINITION for database slot COM.OONET.EDI::EFFECTIVE-DATE-QUALIFIER  
#x8BE961E> #<PERSISTENT-EFFECTIVE-SLOT-DEFINITION for database slot  
COM.OONET.EDI::EFFECTIVE-DATE-QUALIFIER #x8BE961E>)
   1: (#<STANDARD-METHOD SHARED-INITIALIZE :AROUND  
(ELEPHANT:PERSISTENT-OBJECT T)> #<COM.OONET.EDI:834-ENTRY #x8CCB1A6> 'T)
   2: (CCL::%%CNM-WITH-ARGS-COMBINED-METHOD-DCODE '(NIL  
#<CCL::STANDARD-KERNEL-METHOD INITIALIZE-INSTANCE (STANDARD-OBJECT) 
 > . 10540825) '((#<STANDARD-METHOD INITIALIZE-INSTANCE :BEFORE #>)  
NIL #<CCL::STANDARD-KERNEL-METHOD INITIALIZE-INSTANCE (STANDARD- 
OBJECT)>) 10540825)
   3: (CCL::%%STANDARD-COMBINED-METHOD-DCODE 'NIL  
#<ELEPHANT:PERSISTENT-METACLASS COM.OONET.EDI:834-ENTRY>)
   4: (CCL::%MAKE-STD-INSTANCE #<COM.OONET.EDI:834-ENTRY #x8CCC40E>  
'("INS" "Y" "18" "001" "25" "A" "" "" "FT"))
   5: (#<CCL::STANDARD-KERNEL-METHOD MAKE-INSTANCE (STANDARD-CLASS)>  
#<ELEPHANT:PERSISTENT-METACLASS COM.OONET.EDI:834-ENTRY>)
   6: (CCL::%MAKE-INSTANCE '(COM.OONET.EDI:834-ENTRY .  
#<ELEPHANT:PERSISTENT-METACLASS COM.OONET.EDI:834-ENTRY>))
   7: (COM.OONET.EDI::PARSE-834-FILE #<FILE-CHARACTER-INPUT-STREAM ("/ 
Users/dsalama/Documents/Projects/MCNA/DHACS/RDTLMCNA0106.EDI"/14)  
#x8BF207E>)
   8: (COM.OONET.EDI:LOAD-834-TAPE "RDTLMCNA0106.EDI")
   9: (CCL::REPORT-TIME '(COM.OONET.EDI:LOAD-834-TAPE  
"RDTLMCNA0106.EDI") #<Anonymous Function #x8BF20EE>)
10: (CCL::CALL-CHECK-REGS 'CCL::REPORT-TIME)
11: (SWANK::EVAL-REGION "(time (oonet:load-834-tape \"RDTLMCNA0106.EDI 
\"))
" 'T)
12: (#<Anonymous Function #x85286E6> "(time (oonet:load-834-tape  
\"RDTLMCNA0106.EDI\"))
")
13: (SWANK::CALL-WITH-BUFFER-SYNTAX #<COMPILED-LEXICAL-CLOSURE  
#x8BF2716>)
14: (CCL::CALL-CHECK-REGS 'SWANK:LISTENER-EVAL)
15: (#<Anonymous Function #x8516CA6> '(SWANK:LISTENER-EVAL "(time  
(oonet:load-834-tape \"RDTLMCNA0106.EDI\"))
") 47 "COMMON-LISP-USER")
16: (#<STANDARD-METHOD SWANK-BACKEND:CALL-WITH-DEBUGGER-HOOK (T T)>  
#<Compiled-function SWANK:SWANK-DEBUGGER-HOOK #x8527576> #<COMPILED- 
LEXICAL-CLOSURE #x8BF2756>)
17: (FUNCALL 'SWANK::EVAL-FOR-EMACS)
18: (#<Anonymous Function #x8504C96>)
19: (#<Anonymous Function #x8508D56> #<Anonymous Function #x8504C96>)
20: (SWANK::CALL-WITH-REDIRECTED-IO #<COMPILED-LEXICAL-CLOSURE  
#x8B9D596> #<CONNECTION  #x899E8F6>)
21: (SWANK::CALL-WITH-CONNECTION #<CONNECTION  #x899E8F6> #<Anonymous  
Function #x8504C96>)
22: (SWANK::HANDLE-REQUEST #<CONNECTION  #x899E8F6>)
23: (#<Anonymous Function #x85013B6> #<CONNECTION  #x899E8F6>)
24: (#<Anonymous Function #x8508D56> #<COMPILED-LEXICAL-CLOSURE  
#x89D9606>)
25: (SWANK::CALL-WITH-REDIRECTED-IO #<COMPILED-LEXICAL-CLOSURE  
#x89D95EE> 'NIL)
26: (SWANK::CALL-WITH-CONNECTION #<CONNECTION  #x899E8F6> #<COMPILED- 
LEXICAL-CLOSURE #x89D9606>)
27: (SWANK::CALL-WITH-BINDINGS 'NIL #<COMPILED-LEXICAL-CLOSURE  
#x89D961E>)
28: (CCL::RUN-PROCESS-INITIAL-FORM '(#<COMPILED-LEXICAL-CLOSURE  
#x89D87AE>) #<PROCESS new-repl-thread(38) [Active] #x89D87E6>)
29: (#<Anonymous Function #x80DB61E> '(#<COMPILED-LEXICAL-CLOSURE  
#x89D87AE>) 0)
30: (#<Anonymous Function #x80CE806> 790176 #<LISP-THREAD new-repl- 
thread [tcr @ #x303A80] #x89D88D6>)

It seems it dies after processing about 430 objects.

Is there a fix for this? Is there a work around? How about, is there  
a way that I could commit every 100 objects within a nested  
transaction? Will it help?

Thanks,
Waldo