Hi,
I have a tool which compares live data between two sources. I found
that the program runs more than 3 times slower than the same with
guile-2.0.11 . I have done profiling but there was nothing special to point
out. All most all calls were taking more than double the time compare to
guile-2.0.11. It is contrary to the claim of 30% performance boost with
guile-2.2 release. Can some one point the possible reason for slowness?
I have created a simple test program which reports the diff of two alist.
*time /home/guile-2.2/bin/guile -s ./performanceTest.scm*
real 0m34.375s
user 0m37.616s
sys 0m0.361s
*time /home/guile-2.0/bin/guile -s ./performanceTest.scm*
real 0m18.939s
user 0m18.829s
sys 0m0.104s
*Test Code:*
*(use-modules (ice-9 eval-string) (ice-9 common-list) (ice-9 hash-table)
*
* (srfi srfi-1) (ice-9 rdelim))*
*(define *obj-string-cache* (make-hash-table 500))*
*(define (fast-obj-string obj)*
* (let ((entry (hashq-ref *obj-string-cache* obj #f)))*
* (unless entry*
* (set! entry (if (symbol? obj) (symbol->string obj) (object->string
obj)))*
* (hashq-set! *obj-string-cache* obj entry))*
* entry))*
*(define (sort-tuples tuples)*
* (sort-list tuples (lambda (x y) (string<? (fast-obj-string (car x))
(fast-obj-string (car y))))))*
*(define (report-diff type tuple1 tuple2)*
* (let ((tuple (if tuple1 tuple1 tuple2)))*
* (cond ((eq? type '-) `((- . (,tuple1))))*
* ((eq? type '+) `((+ . (,tuple2))))*
* ((eq? type '!) `((! . (,tuple1 . (,tuple2))))))))*
*(define (diff-sorted-tuples tuples1 tuples2 diff)*
* (cond ((and (null? tuples1) (null? tuples2)) diff)*
* ((null? tuples1) (append (map (lambda (x) (report-diff '+ #f x))
tuples2) diff))*
* ((null? tuples2) (append (map (lambda (x) (report-diff '- x #f))
tuples1) diff))*
* (else*
* (let* ((tuple1 (car tuples1))*
* (tuple2 (car tuples2)))*
* (cond ((equal? (car tuple1) (car tuple2))*
* (diff-sorted-tuples (cdr tuples1) (cdr tuples2)*
* (if (equal? tuple1 tuple2) diff
(append! diff (report-diff '! tuple1 tuple2)))))*
* ((string<? (fast-obj-string (car tuple1))*
* (fast-obj-string (car tuple2)))*
* (diff-sorted-tuples (cdr tuples1) tuples2 (append! diff
(report-diff '- tuple1 #f))))*
* (else*
* (diff-sorted-tuples tuples1 (cdr tuples2) (append! diff
(report-diff '+ #f tuple2)))))))))*
*(define-inlinable (diff-tuples tuples1 tuples2)*
* (diff-sorted-tuples (sort-tuples tuples1) (sort-tuples tuples2) '()))*
*(define compare*
* (let ((count 0))*
* (lambda (port)*
* (let ((msg (eval-string (read-line port))))*
* (diff-tuples msg msg)*
* (seek port 0 SEEK_SET)*
* (set! count (1+ count))*
* (if (< count 10000) *
* (compare port))))))*
*(compare (open-input-file "data.txt"))*
*File data.txt*
*'( (IDN_PROD_PERM 98) (RDNDISPLAY 120) (DSPLY_NAME "MINI GOLD JUN7")
(RDN_EXCHID 23) (TIMACT "2017-03-20 10:33:06") (FID_TRD_PRC 1235.2)
(FID_TRD_PREV1_PRC 1234.7) (FID_TRD_PREV2_PRC 1234.8) (TRDPRC_4 1234.7)
(TRDPRC_5 1234.7) (FID_NET_CHG 2.0) (FID_HI 1237.2) (FID_LO 1233.0)
(FID_TICK 1) (CURRENCY 840) (TRADE_DATE "3/20/2017") (ACTIV_DATE
"3/20/2017") (TRDTIM_1 "2017-03-20 10:17:32") (OPEN_PRC 1233.3)
(FID_YSET_PRC 1233.2) (FID_BID 1235.1) (FID_ASK 1235.6) (NEWS "YYYY")
(NEWS_TIME " 7:53:07") (FID_BID_SIZE 5) (FID_ASK_SIZE 1) (FID_CUM_VOL 30)
(CONTR_MNTH "JUN7") (BLKVOLUM null) (FID_SRC_PRC_FMT_CODE 1) (LOTSZUNITS
32) (FID_PCNT_CHG 0.16) (OPEN_BID 1220.7) (OPEN_ASK 1234.0) (CLOSE_BID
1231.4) (CLOSE_ASK 1232.9) (LOCHIGH 1365.3) (LOCLOW 1098.0) (FID_OPN_INT
165) (OPINTNC 23) (FID_EXPR "6/28/2017") (FID_SET_PRC 1233.2) (UPLIMIT
null) (LOLIMIT null) (FID_NO_OF_TRDS 26) (OFFCL_CODE "5050169")
(FID_IDN_HSTCLSDATE "3/17/2017") (LIMIT_IND null) (TURNOVER 32109.0)
(YCHIGH_IND null) (YCLOW_IND null) (DAYS_MAT 101) (PRC_QL_CD 160)
(TDY_UN_CLS null) (TDY_OF_CLS null) (FID_TRD_VOL 1) (LOT_SIZE_A 32.15)
(RECORDTYPE 178) (FID_SET_DATE "3/17/2017") (BID_TONE "i") (ASK_TONE "i")
(OPINT_2 142) (OPINT_DATE "3/17/2017") (IRGVOL null) (INSPRC null) (INSVOL
null) (FID_TRD_TIME "2017-03-20 10:17:32") (TNOVER_SC null) (HST_VOL null)
(EXERCISED null) (BCAST_REF "GOL") (HST_SESVOL 56) (ACT_FLAG1 "s")
(ACT_FLAG2 "s") (ACT_FLAG3 "b") (ACT_FLAG4 "b") (ACT_FLAG5 " ") (GEN_VAL1
1235.4) (GEN_VAL2 1.0) (GEN_VAL3 1233.4) (GEN_VAL4 101) (GV1_TEXT "SPLTrd")
(GV2_TEXT "SPLVol") (GV3_TEXT "SYS") (SEQNUM 52690211) (QUOTIM "2017-03-20
10:33:06") (GV1_DATE "3/20/2017") (GEN_VAL5 null) (GV1_TIME "2017-03-20
10:19:15") (EXCHTIM "2017-03-20 10:33:06") (CONV_FAC 0) (PREF_DISP 5391)
(VOL_X_PRC1 1234.96) (DSO_ID null) (BIG_VOL null) (RDN_EXCHD2 759)
(THEO_OPEN 1233.4) (LSTTRDDATE null) (OPINT_DAT2 "3/16/2017") (PREV_DISP
3491) (MPV null) (OFF_CLOSE null) (QUOTE_DATE "3/20/2017") (TRDVOL_2 1)
(TRDVOL_3 1) (TRDVOL_4 1) (TRDVOL_5 1) (VWAP 1234.96) (PROV_SYMB "5050169")
(BID_ASK_DT "3/17/2017") (ISIN_CODE null) (LST_TRD_PR 1232.1) (MNEMONIC
"YG") (UNDERLYING null) (PERIOD_CDE "O") (TRDTIM_MS 51452672) (SALTIM_MS
51452672) (QUOTIM_MS 52386000) )*
*Profile output comparison*
*GUILE 2.0.11*
*% cumulative self*
*time seconds seconds name*
62.15 11.87 11.87 read
7.56 1.44 1.44 string<?
6.91 3.55 1.32 #<procedure b60d8b0 at
./performanceTest1.scm:23:20 (x y)>
6.51 1.24 1.24 %read-line
5.86 2.23 1.12 fast-obj-string
5.80 1.11 1.11 hashq-ref
1.50 5.28 0.29 sort-list
0.91 0.17 0.17 diff-sorted-tuples
0.46 0.09 0.09 #<procedure b786438 at
ice-9/eval-string.scm:73:5 (port)>
0.20 12.09 0.04 read-and-eval
0.20 0.09 0.04 #<procedure aa992a0 at ice-9/boot-9.scm:2777:4
(name #:optional autoload version #:key ensure)>
0.13 19.11 0.02 #<procedure b60d650 at
./performanceTest1.scm:56:5 (port)>
0.13 0.09 0.02 scan
0.13 0.05 0.02 nested-ref-module
0.13 0.05 0.02 #<procedure b6ce410 at
language/scheme/spec.scm:34:16 (port env)>
0.13 0.02 0.02 module-variable
0.13 0.02 0.02 seek
0.07 19.11 0.01 save-module-excursion
0.07 1.26 0.01 read-line
0.07 0.12 0.01 #<procedure aa39470 at ice-9/eval.scm:499:4
(exp)>
0.07 0.10 0.01 expand-top-sequence
0.07 0.06 0.01 lookup-language
0.07 0.06 0.01 syntax-type
0.07 0.02 0.01 module-ref-submodule
0.07 0.01 0.01 #<procedure eeb2050>
0.07 0.01 0.01 #<procedure aa93090 at ice-9/boot-9.scm:2004:2
(module)>
0.07 0.01 0.01 #<procedure aadab00>
0.07 0.01 0.01 variable-ref
0.07 0.01 0.01 #<procedure d11b650>
0.07 0.01 0.01 current-module
0.07 0.01 0.01 assq
0.07 0.01 0.01 #<procedure b591cf0 at ice-9/boot-9.scm:1380:4
(obj)>
0.07 0.01 0.01 #<procedure b988120>
0.07 0.01 0.01 memoize-expression
0.07 0.01 0.01 #<procedure ba84230>
0.00 19.11 0.00 eval
0.00 19.11 0.00 load-compiled/vm
0.00 19.11 0.00 #<procedure b60da20 ()>
0.00 19.11 0.00 call-with-prompt
0.00 19.11 0.00 #<procedure b584ce0 at ice-9/boot-9.scm:4045:3
()>
0.00 12.27 0.00 call-with-input-string
0.00 0.12 0.00 lp
0.00 0.07 0.00 eval-string
0.00 0.04 0.00 get-global-definition-hook
0.00 0.01 0.00 #<procedure aa59280 at
ice-9/eval-string.scm:76:8 ()>
0.00 0.01 0.00 module-ref
---
Sample count: 1535
Total time: 19.106 seconds (0.865 seconds in GC)
*GUILE 2.2*
*% cumulative self*
*time seconds seconds procedure*
35.62 13.04 13.02 read
16.47 10.41 6.02 ./performanceTest1.scm:13:0:fast-obj-string
12.06 14.82 4.41 ./performanceTest1.scm:23:20
12.02 4.39 4.39 hashq-ref
9.20 3.36 3.36 string<?
5.64 2.10 2.06 %read-line
5.12 36.54 1.87 ./performanceTest1.scm:56:5
1.11 0.41 0.41 open-input-string
0.96 0.35 0.35 ./performanceTest1.scm:34:0:diff-sorted-tuples
0.19 0.07 0.07 %after-gc-thunk
0.15 13.40 0.05 ice-9/eval-string.scm:33:0:read-and-eval
0.15 0.05 0.05 module-variable
0.11 0.07 0.04 ice-9/boot-9.scm:2485:0:nested-ref-module
0.11 0.04 0.04 set-current-module
0.07 0.09 0.03 ice-9/psyntax.scm:1083:10:parse
0.07 0.07 0.03 language/scheme/spec.scm:34:16
0.07 0.05 0.03 ice-9/eval-string.scm:77:8
0.07 0.03 0.03 ice-9/psyntax.scm:2944:8:match
0.04 50.02 0.01 ice-9/boot-9.scm:2306:0:save-module-excursion
0.04 18.20 0.01 sort-list
0.04 0.42 0.01 ice-9/ports.scm:526:0:call-with-input-string
0.04 0.20 0.01 ice-9/eval.scm:40:0:primitive-eval
0.04 0.18 0.01 ice-9/psyntax.scm:1054:6:expand-top-sequence
0.04 0.12 0.01 ice-9/eval-string.scm:56:0:eval-string
0.04 0.09 0.01 ice-9/boot-9.scm:2699:4
0.04 0.07 0.01 ice-9/psyntax.scm:872:4:resolve-identifier
0.04 0.05 0.01 ice-9/boot-9.scm:228:5:map1
0.04 0.03 0.01 ice-9/boot-9.scm:2293:0:module-ref-submodule
0.04 0.03 0.01 ice-9/eval-string.scm:28:0:ensure-language
0.04 0.01 0.01 memq
0.04 0.01 0.01 ice-9/boot-9.scm:1975:2
0.04 0.01 0.01 ice-9/boot-9.scm:1293:2
0.04 0.01 0.01 variable-ref
0.04 0.01 0.01 list?
0.04 0.01 0.01 ice-9/psyntax.scm:767:10:search
0.04 0.01 0.01 ice-9/boot-9.scm:1371:17
0.04 0.01 0.01 variable-bound?
0.04 0.01 0.01 ice-9/boot-9.scm:1975:2
0.04 0.01 0.01 ice-9/boot-9.scm:1306:4
0.00 36.54 0.00 apply-smob/1
0.00 36.54 0.00 ice-9/eval.scm:618:6
0.00 36.54 0.00 ice-9/boot-9.scm:709:0:call-with-prompt
0.00 36.54 0.00 ice-9/boot-9.scm:3821:3
0.00 36.54 0.00 anon #xec651098
0.00 2.10 0.00 ice-9/rdelim.scm:193:0:read-line
0.00 0.14 0.00 ice-9/psyntax.scm:1289:6:syntax-type
0.00 0.09 0.00 system/base/language.scm:61:0:lookup-language
0.00 0.07 0.00 anon #xfce2f8
0.00 0.03 0.00 ice-9/psyntax.scm:2043:19
0.00 0.03 0.00 ice-9/psyntax.scm:2907:8:match*
0.00 0.01 0.00 ice-9/psyntax.scm:1950:6:strip
0.00 0.01 0.00 ice-9/boot-9.scm:223:2:map
0.00 0.01 0.00 ice-9/psyntax.scm:762:6:id-var-name
0.00 0.01 0.00 ice-9/eval-string.scm:66:9
0.00 0.01 0.00 ice-9/psyntax.scm:2695:10:macroexpand
0.00 0.01 0.00 ice-9/psyntax.scm:2046:26
0.00 0.01 0.00 ice-9/boot-9.scm:2611:4
---
Sample count: 2695
Total time: 36.543 seconds (0.539 seconds in GC)
Thanks
- vijay
