memory leak when using {%include%} and {%if%}

[ShredderMing]

[mmontone]

Nice test.

Is it only when using "if"?

[ShredderMing]

I'm not sure. I was accidentally found this when i build my website with caveman.

[fisxoj]

Got interested in this recently, since I'm using djula for my site, as well. Profiling 1000 runs of @ShredderMing s test case gives this result:

  seconds  |     gc     |    consed   |  calls  |  sec/call  |  name  
-----------------------------------------------------------
    12.258 |      0.000 |  14,391,664 |   1,000 |   0.012258 | DJULA::COMPILE-LOGICAL-STATEMENT
     0.170 |      0.159 |  20,508,800 |  60,000 |   0.000003 | DJULA::BLITERAL
     0.105 |      0.000 |  12,302,256 |   2,000 |   0.000053 | DJULA::SLURP
     0.093 |      0.000 |  16,349,264 |   4,000 |   0.000023 | DJULA:FIND-TEMPLATE
     0.030 |      0.000 |      32,688 |   4,000 |   0.000008 | DJULA::SEMI-PARSE-TAG
     0.024 |      0.000 |           0 |  16,000 |   0.000001 | DJULA::FIND-TOKEN-PROCESSOR
     0.018 |      0.000 |  26,533,136 |  20,000 |   0.000001 | DJULA::COMPARISON-OPERATOR-PARSER
     0.015 |      0.000 |           0 |   8,000 |   0.000002 | DJULA::FIND-TOKEN-COMPILER
     0.008 |      0.000 |           0 |   2,000 |   0.000004 | DJULA:FETCH-TEMPLATE
     0.007 |      0.000 |   4,056,288 |   4,000 |   0.000002 | DJULA::PARSE-REST-OF-TAG
     0.006 |      0.000 |           0 |   4,000 |   0.000002 | DJULA::FIND-TAG-PROCESSOR
     0.006 |      0.000 |           0 |   4,000 |   0.000002 | DJULA::PARSE-TAG
     0.005 |      0.000 |           0 |   6,000 |   0.000001 | DJULA.TOKEN-COMPILERS:STRING
     0.005 |      0.000 |           0 |   1,000 |   0.000005 | DJULA::GET-VARIABLE

It looks like DJULA::COMPILE-LOGICAL-STATEMENT is probably to blame and it's also the one calling BLITERAL. I'm going to keep digging, but maybe you two have some insight, having looked at this already.

Also, SLURP being called every time the template is rendered seems weird to me. Is it re-reading the template from disk for each render?

[mmontone]

Thanks for the report. I'll have a look when I have time.

No. SLURP should not be being called every time at all.

[mmontone]

Ok. In my tests, there seems to be no problem with the if conditional if no include is used. Also, I don't see the SLURP function being called.

                                                        Cons
                          %     %                       Per      Total   Total
Function                  Time  Cons  Calls  Sec/Call   Call     Time    Cons
-------------------------------------------------------------------------------
RENDER-TEMPLATE*:         0.44  0.00  1000000  0.000008      0  7.558000       0
COMPILE-BOOLEXP:          0.09  0.00  1000000  0.000001      0  1.493000       0
INTEGER-OR-KEYWORD:       0.08  0.00  1000000  0.000001      0  1.429000       0
RESOLVE-VARIABLE-PHRASE:  0.08  0.00  1000000  0.000001      0  1.398000       0
GET-VARIABLE:             0.07  0.00  1000000  0.000001      0  1.282000       0
PARSE-VARIABLE-PHRASE:    0.07  0.00  1000000  0.000001      0  1.275000       0
APPLY-KEYS/INDEXES:       0.04  0.00  1000000  0.000001      0  0.605000       0
LINKED-FILES:             0.03  0.00  1000000  0.000001      0  0.559000       0
TEMPLATE-FILE-WRITE-DATE: 0.03  0.00  1000000  0.000001      0  0.549000       0
COMPILED-TEMPLATE:        0.03  0.00  1000000  0.000000      0  0.487000       0
TEMPLATE-FILE:            0.03  0.00  1000002  0.000000      0  0.469000       0
-------------------------------------------------------------------------------
TOTAL:                    1.00  0.00  11000002                   17.103998       0
Estimated monitoring overhead: 0.00 seconds
Estimated total monitoring overhead: 0.00 seconds
Twenty-five monitored functions were not called. 
See the variable mon::*no-calls* for a list.

Maybe I'm wrong. @fisxoj what are you using for the profiling? That could help me.

Will try with an include now.

[mmontone]

Same result when rendering the include:

DJULA> (mon:reset-all-monitoring)
NIL
DJULA> (mon:monitor-all)
NIL
DJULA> (loop repeat 1000000 do (djula:render-template* +include.html+ nil :flag t))
NIL
DJULA> (djula:render-template* +include.html+ nil :flag t)
"
yes

"
DJULA> (mon:report-monitoring)
                                                        Cons
                          %     %                       Per      Total   Total
Function                  Time  Cons  Calls  Sec/Call   Call     Time    Cons
-------------------------------------------------------------------------------
RENDER-TEMPLATE*:         0.64  0.00  1000001  0.000022      0  22.302000       0
INTEGER-OR-KEYWORD:       0.05  0.00  1000001  0.000002      0  1.647000       0
COMPILE-BOOLEXP:          0.04  0.00  1000001  0.000001      0  1.492000       0
RESOLVE-VARIABLE-PHRASE:  0.04  0.00  1000001  0.000001      0  1.467000       0
GET-VARIABLE:             0.04  0.00  1000001  0.000001      0  1.373000       0
PARSE-VARIABLE-PHRASE:    0.04  0.00  1000001  0.000001      0  1.328000       0
LINKED-FILES:             0.03  0.00  2000002  0.000001      0  1.166000       0
COMPILED-TEMPLATE:        0.03  0.00  2000002  0.000001      0  1.151000       0
TEMPLATE-FILE-WRITE-DATE: 0.03  0.00  2000002  0.000001      0  1.077000       0
TEMPLATE-FILE:            0.03  0.00  2000002  0.000001      0  1.054000       0
APPLY-KEYS/INDEXES:       0.02  0.00  1000001  0.000001      0  0.615000       0
-------------------------------------------------------------------------------
TOTAL:                    1.00  0.00  15000015                   34.672000       0
Estimated monitoring overhead: 0.00 seconds
Estimated total monitoring overhead: 0.00 seconds
Sixty-three monitored functions were not called. 
See the variable mon::*no-calls* for a list.

I don't see the leak. :-/

[fisxoj]

Yes, that's the tricky bit. I've also been able to get profiles like that. Then, it changes to the other case and I'm not sure what causes it to happen. One time I changed the indentation of the nav bar file and it went from fast (not reloading the templates) to slow (re-parsing every time). I'm trying to look at how the templates are cached because that seems to be the real problem: I can't predict when it will use the cached version or when it will reload. I can upload my precise method later, but it's essentially what is shown in the screen capture.

On Wed, Apr 27, 2016, 4:59 PM Mariano Montone notifications@github.com wrote:

Ok. In my tests, there seems to be no problem with the if conditional if no include is used. Also, I don't see the SLURP function being called.

                                                    Cons
                      %     %                       Per      Total   Total

Function Time Cons Calls Sec/Call Call Time Cons

RENDER-TEMPLATE*: 0.44 0.00 1000000 0.000008 0 7.558000 0 COMPILE-BOOLEXP: 0.09 0.00 1000000 0.000001 0 1.493000 0 INTEGER-OR-KEYWORD: 0.08 0.00 1000000 0.000001 0 1.429000 0 RESOLVE-VARIABLE-PHRASE: 0.08 0.00 1000000 0.000001 0 1.398000 0 GET-VARIABLE: 0.07 0.00 1000000 0.000001 0 1.282000 0 PARSE-VARIABLE-PHRASE: 0.07 0.00 1000000 0.000001 0 1.275000 0 APPLY-KEYS/INDEXES: 0.04 0.00 1000000 0.000001 0 0.605000 0 LINKED-FILES: 0.03 0.00 1000000 0.000001 0 0.559000 0 TEMPLATE-FILE-WRITE-DATE: 0.03 0.00 1000000 0.000001 0 0.549000 0 COMPILED-TEMPLATE: 0.03 0.00 1000000 0.000000 0 0.487000 0

TEMPLATE-FILE: 0.03 0.00 1000002 0.000000 0 0.469000 0

TOTAL: 1.00 0.00 11000002 17.103998 0 Estimated monitoring overhead: 0.00 seconds Estimated total monitoring overhead: 0.00 seconds Twenty-five monitored functions were not called. See the variable mon::no-calls for a list.

Maybe I'm wrong. @fisxoj https://github.com/fisxoj what are you using for the profiling? That could help me.

Will try with an include now.

— You are receiving this because you were mentioned.

Reply to this email directly or view it on GitHub https://github.com/mmontone/djula/issues/32#issuecomment-215227427

[mmontone]

On 27/04/16 18:08, Matt Novenstern wrote:

Yes, that's the tricky bit. I've also been able to get profiles like that. Then, it changes to the other case and I'm not sure what causes it to happen. One time I changed the indentation of the nav bar file and it went from fast (not reloading the templates) to slow (re-parsing every time). I'm trying to look at how the templates are cached because that seems to be the real problem: I can't predict when it will use the cached version or when it will reload. I can upload my precise method later, but it's essentially what is shown in the screen capture.

Ah. Ok. There must be some bug in the cache then.

[mmontone]

I've managed to reproduce the bug. Changed the included template and got slow.

[mmontone]

My first guess is that the modified included template is not being cached properly.

[mmontone]

I know where the problem is now. And have a potential fix. But will need some testing before commit.

[mmontone]

I've commited what I think is a fix in 52177984d4631a6a0a537d3a81b2dec30441ff46

@ShredderMing @fisxoj please reopen if you still see the problem.