Velocity
  1. Velocity
  2. VELOCITY-24

calls to local macros not always made when template caching is off

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 1.5 beta1
    • Fix Version/s: 1.5
    • Component/s: Engine
    • Labels:
      None
    • Environment:
      Operating System: other
      Platform: Other

      Description

      In the latest nightly build Oct 28, 2001 and also in velocity 1.2 rc2 i noticed
      the following problem with autoreloading macros.

      Made a simple html page. added a simple one line macro that accepted one param,
      a letter
      something like....

        1. local macro, not global
          #macro(letter $char)
          This is the letter $char
          #end

      #letter("A")
      #letter("B")
      #letter("C")

      etc.... to Z

      ------
      The html page would be loaded in response to a form being submitted. If I
      clicked on the submit button five times, quickly ( five separate submits), most
      times the final response would out put something like...


      This is the letter A
      This is the letter B
      This is the letter C
      This is the letter D
      This is the letter E
      #letter #letter #letter
      #letter ......
      This is the letter Z

      As you can see, some macro calls did not get parsed.

      We were just happening to use velocity through turbine, but I don't think that
      affects the bug. Besides, the bug went away when the autoreload was false.

      Once scarab's runbox is back up, might be interesting to test this out on their
      macros too for comparison, although I don't see that they have any local macros.

        Issue Links

          Activity

          Hide
          Geir Magnusson Jr added a comment -

          thanks. will duplicate and fix.

          Show
          Geir Magnusson Jr added a comment - thanks. will duplicate and fix.
          Hide
          Jon Stevens added a comment -

          fyi, the runbox is back up. for some reason, the httpd died.

          Show
          Jon Stevens added a comment - fyi, the runbox is back up. for some reason, the httpd died.
          Hide
          peterwlynch added a comment -

          The exact conditions in which this issue can be reproduced are as follows:

          1. autoload off and caching templates off, using local macro, able to reproduce

          2. autoload off and caching on, using local macro, NOT able to reproduce

          It appears more of a caching issue, therefore changing the summary accordingly.

          Show
          peterwlynch added a comment - The exact conditions in which this issue can be reproduced are as follows: 1. autoload off and caching templates off, using local macro, able to reproduce 2. autoload off and caching on, using local macro, NOT able to reproduce It appears more of a caching issue, therefore changing the summary accordingly.
          Hide
          Geir Magnusson Jr added a comment -

          thanks. on it...

          Show
          Geir Magnusson Jr added a comment - thanks. on it...
          Hide
          Geir Magnusson Jr added a comment -

          There is a bit of a red herring here - I realized this when I was looking over
          our public and private conversations - you have a whole pile of related
          switches set.

          It turns out to be inline.local + cache off -> because what happens is that
          with no caching, it's possible for the VM namespace to get dumped during
          the parse of one thread, while another thread is init-ing the AST.

          There are a few solutions - will play and report back. The key is to not
          crush performance in general to fix a problem that you only see in what is
          mostly un-realistic configurations - high load, cache off.

          Show
          Geir Magnusson Jr added a comment - There is a bit of a red herring here - I realized this when I was looking over our public and private conversations - you have a whole pile of related switches set. It turns out to be inline.local + cache off -> because what happens is that with no caching, it's possible for the VM namespace to get dumped during the parse of one thread, while another thread is init-ing the AST. There are a few solutions - will play and report back. The key is to not crush performance in general to fix a problem that you only see in what is mostly un-realistic configurations - high load, cache off.
          Hide
          Geoffrey Picron added a comment -

          Think it is link this bug

          Show
          Geoffrey Picron added a comment - Think it is link this bug
          Hide
          Daniel Rall added a comment -

          Geoffrey, what release did you see this bug in?

          Show
          Daniel Rall added a comment - Geoffrey, what release did you see this bug in?
          Hide
          Daniel Rall added a comment -

          To answer my own question, 1.3.1 is the version Geoff used in dependent bug 24115.

          Show
          Daniel Rall added a comment - To answer my own question, 1.3.1 is the version Geoff used in dependent bug 24115.
          Hide
          Henning Schmiedehausen added a comment -

          Issue is trivially reproducable using ab -c 2 -n 8 http://localhost:8080/testbed/templates/issues/velocity-24.vm

          There definitely is a race condition somewhere in the Velocity engine that should be fixed for 1.5. Raising prio to blocker for 1.5.

          Show
          Henning Schmiedehausen added a comment - Issue is trivially reproducable using ab -c 2 -n 8 http://localhost:8080/testbed/templates/issues/velocity-24.vm There definitely is a race condition somewhere in the Velocity engine that should be fixed for 1.5. Raising prio to blocker for 1.5.
          Hide
          Will Glass-Husain added a comment -

          FYI. I've also hit this issue independently with repeated calls to macros in a page that merged simultaneously by a bunch of web requests. (in a production system). Been meaning to dig into this.

          WILL

          Show
          Will Glass-Husain added a comment - FYI. I've also hit this issue independently with repeated calls to macros in a page that merged simultaneously by a bunch of web requests. (in a production system). Been meaning to dig into this. WILL
          Hide
          Henning Schmiedehausen added a comment -

          hmmm. it seems that the whole getTemplate() path is not really threadsafe with respect to local macros. The culprit lies in the dumpNamespace() methods. Will investigate further...

          Show
          Henning Schmiedehausen added a comment - hmmm. it seems that the whole getTemplate() path is not really threadsafe with respect to local macros. The culprit lies in the dumpNamespace() methods. Will investigate further...
          Hide
          Henning Schmiedehausen added a comment -

          getResource() must be synchronized. Yes, that sucks for applications that hammer on that and have caching off. Here are some numbers (running on my shiny new Core 2 Duo box, Tomcat and VelocityViewServlet running under the debugger)

          ab -c 5 -n 1000 http://localhost:8080/testbed/templates/issues/velocity-24.vm

          unsynced, caching off:

          Document Path: /testbed/templates/issues/velocity-24.vm
          Document Length: 663 bytes

          Concurrency Level: 5
          Time taken for tests: 4.193717 seconds
          Complete requests: 1000
          Failed requests: 760 <-------------------------- !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
          (Connect: 0, Length: 760, Exceptions: 0)
          Write errors: 0
          Total transferred: 595970 bytes
          HTML transferred: 449860 bytes
          Requests per second: 238.45 /sec (mean)
          Time per request: 20.969 [ms] (mean)
          Time per request: 4.194 [ms] (mean, across all concurrent requests)
          Transfer rate: 138.78 [Kbytes/sec] received

          unsynced, cache on:

          Document Path: /testbed/templates/issues/velocity-24.vm
          Document Length: 663 bytes

          Concurrency Level: 5
          Time taken for tests: 0.479525 seconds
          Complete requests: 1000
          Failed requests: 0
          Write errors: 0
          Total transferred: 809809 bytes
          HTML transferred: 663663 bytes
          Requests per second: 2085.40 /sec (mean)
          Time per request: 2.398 [ms] (mean)
          Time per request: 0.480 [ms] (mean, across all concurrent requests)
          Transfer rate: 1647.46 [Kbytes/sec] received

          synced, cache off:

          Document Path: /testbed/templates/issues/velocity-24.vm
          Document Length: 663 bytes

          Concurrency Level: 5
          Time taken for tests: 11.92560 seconds
          Complete requests: 1000
          Failed requests: 0
          Write errors: 0
          Total transferred: 809000 bytes
          HTML transferred: 663000 bytes
          Requests per second: 90.15 /sec (mean)
          Time per request: 55.463 [ms] (mean)
          Time per request: 11.093 [ms] (mean, across all concurrent requests)
          Transfer rate: 71.22 [Kbytes/sec] received

          synced, cache on

          Document Path: /testbed/templates/issues/velocity-24.vm
          Document Length: 663 bytes

          Concurrency Level: 5
          Time taken for tests: 0.333444 seconds
          Complete requests: 1000
          Failed requests: 0
          Write errors: 0
          Total transferred: 810618 bytes
          HTML transferred: 664326 bytes
          Requests per second: 2999.00 /sec (mean)
          Time per request: 1.667 [ms] (mean)
          Time per request: 0.333 [ms] (mean, across all concurrent requests)
          Transfer rate: 2372.21 [Kbytes/sec] received

          The response time for cache on (which should be the normal production mode) is about the same level for synced and unsynced. But without cache, syncing makes the difference between "fast but wrong" and "slower but correct". I personally opt for the latter.

          Show
          Henning Schmiedehausen added a comment - getResource() must be synchronized. Yes, that sucks for applications that hammer on that and have caching off. Here are some numbers (running on my shiny new Core 2 Duo box, Tomcat and VelocityViewServlet running under the debugger) ab -c 5 -n 1000 http://localhost:8080/testbed/templates/issues/velocity-24.vm unsynced, caching off: Document Path: /testbed/templates/issues/velocity-24.vm Document Length: 663 bytes Concurrency Level: 5 Time taken for tests: 4.193717 seconds Complete requests: 1000 Failed requests: 760 <-------------------------- !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (Connect: 0, Length: 760, Exceptions: 0) Write errors: 0 Total transferred: 595970 bytes HTML transferred: 449860 bytes Requests per second: 238.45 /sec (mean) Time per request: 20.969 [ms] (mean) Time per request: 4.194 [ms] (mean, across all concurrent requests) Transfer rate: 138.78 [Kbytes/sec] received unsynced, cache on: Document Path: /testbed/templates/issues/velocity-24.vm Document Length: 663 bytes Concurrency Level: 5 Time taken for tests: 0.479525 seconds Complete requests: 1000 Failed requests: 0 Write errors: 0 Total transferred: 809809 bytes HTML transferred: 663663 bytes Requests per second: 2085.40 /sec (mean) Time per request: 2.398 [ms] (mean) Time per request: 0.480 [ms] (mean, across all concurrent requests) Transfer rate: 1647.46 [Kbytes/sec] received synced, cache off: Document Path: /testbed/templates/issues/velocity-24.vm Document Length: 663 bytes Concurrency Level: 5 Time taken for tests: 11.92560 seconds Complete requests: 1000 Failed requests: 0 Write errors: 0 Total transferred: 809000 bytes HTML transferred: 663000 bytes Requests per second: 90.15 /sec (mean) Time per request: 55.463 [ms] (mean) Time per request: 11.093 [ms] (mean, across all concurrent requests) Transfer rate: 71.22 [Kbytes/sec] received synced, cache on Document Path: /testbed/templates/issues/velocity-24.vm Document Length: 663 bytes Concurrency Level: 5 Time taken for tests: 0.333444 seconds Complete requests: 1000 Failed requests: 0 Write errors: 0 Total transferred: 810618 bytes HTML transferred: 664326 bytes Requests per second: 2999.00 /sec (mean) Time per request: 1.667 [ms] (mean) Time per request: 0.333 [ms] (mean, across all concurrent requests) Transfer rate: 2372.21 [Kbytes/sec] received The response time for cache on (which should be the normal production mode) is about the same level for synced and unsynced. But without cache, syncing makes the difference between "fast but wrong" and "slower but correct". I personally opt for the latter.
          Hide
          Will Glass-Husain added a comment -

          So, it cuts the speed in half for uncached operation?

          Seems acceptable to me, since we offer a pretty good cache.

          Nice work on tracking this down and solving it.

          Show
          Will Glass-Husain added a comment - So, it cuts the speed in half for uncached operation? Seems acceptable to me, since we offer a pretty good cache. Nice work on tracking this down and solving it.
          Hide
          Henning Schmiedehausen added a comment -

          Close all resolved issues for Engine 1.5 release.

          Show
          Henning Schmiedehausen added a comment - Close all resolved issues for Engine 1.5 release.

            People

            • Assignee:
              Henning Schmiedehausen
              Reporter:
              peterwlynch
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development