[REBOL] Profiling Rebol API to DyBASE
From: knizhnik::garret::ru at: 18-Dec-2003 20:43
Hello Konstantin,
Looks there is no profiler in Rebol:(
So, I have to do profiling myself using now/time/precise.
I got the following results which seems to be interesting:
Elapsed time for inserting 100000 records: 0:01:01
Elapsed time for performing 200000 index searches: 0:02:06
Time spent in lookup 0:01:24.312
Time spent in lookup/select 0:00:53.348
Time spent in lookup/make 0:00:11.418
Time spent in lookup/insert 0:00:01.501
Time spent in lookup/fetch 0:00:11.401
Time spent in find 0:01:58.464
Time spent in find/iterator creation 0:00:14.281
Time spent in find/append 0:01:36.118
Elapsed time for iterating through 200000 records: 0:03:02
Time spent in lookup 0:02:54.861
Time spent in lookup/select 0:01:56.736
Time spent in lookup/make 0:00:23.251
Time spent in lookup/insert 0:00:03.774
Time spent in lookup/fetch 0:00:23.006
Elapsed time for deleting 100000 records: 0:03:53
Time spent in lookup 0:01:52.034
Time spent in lookup/select 0:01:21.9
Time spent in lookup/make 0:00:11.587
Time spent in lookup/insert 0:00:01.703
Time spent in lookup/fetch 0:00:12.389
So, during index search 1.5 minutes from 2 were spent in lookup
function. And 14 seconds takes searching index itself.
From these 1.5 minutes most of the time was spent in this line:
obj: select obj-by-oid-map oid
I wrote a large number of test scripts experimenting with hashes,
but could not find the reason of the problem - 100000 searches can be
executed for less then one second.
Below is text of _lookup-function with inserted profiling statement.
May be somebody can explain to me such strange behavior?
obj-by-oid-map maps OID (integer number - object identifier) to
object instances. It is periodically cleared
(using "clear obj-by-oid-map"), so number of elements in hash should
not be larger than 100. And select should always return none.
_lookup-object: function[oid recursive] [h this obj hnd class-name field-name start start2]
[
either oid = 0 [
none
] [
start: now/time/precise
obj: select obj-by-oid-map oid
elapsed-select: elapsed-select + (now/time/precise - start)
either not obj [
start2: now/time/precise
hnd: dybase_begin_load db oid
cls: to word! dybase_get_class_name hnd
this: self
obj: make get cls [__oid__: oid __storage__: this __class__: cls]
if not recursive [
either obj/recursive-loading? [
recursive: true
] [
obj/__raw__: true
]
]
elapsed-make: elapsed-make + (now/time/precise - start2)
start2: now/time/precise
insert insert tail obj-by-oid-map oid obj
elapsed-insert: elapsed-insert + (now/time/precise - start2)
start2: now/time/precise
either find [string-index integer-index decimal-index] cls [
dybase_next_field hnd
obj/index: dybase_get_ref hnd
dybase_next_field hnd
] [
while [not empty? field-name: dybase_next_field hnd] [
set in obj (to word! field-name) _fetch-component hnd recursive
]
if recursive [obj/on-load]
]
elapsed-fetch: elapsed-fetch + (now/time/precise - start2)
] [
if recursive and obj/__raw__ [load-object obj]
]
elapsed-lookup: elapsed-lookup + (now/time/precise - start)
obj
]
]
--
Thanks in advance,
Konstantin mailto:[knizhnik--garret--ru]