Uploaded image for project: 'Bitbucket Server'
  1. Bitbucket Server
  2. BSERV-8690

"Unmatched Timer" error on the profiling log

    XMLWordPrintable

    Details

      Description

      A look at the stash's profiling log of a local instance shows multiple occurrences of the following error:

      Unmatched Timer.  Was expecting "foo" instead got "bar"
      

      For example, this can be seen after a push:

      Unmatched Timer.  Was expecting /usr/local/bin/git receive-pack /Users/pepoirot/Dev/apps-home/stash-default/data/repositories/51, instead got SSH - git-receive-pack '/project_1/linux.git'
      

      This is caused by the combination of two things:

      1. the utilisation of a ThreadLocal in UtilTimerStack to store a snapshot of the current time / memory usage in atlassian-profiling:
        UtilTimerStack.push("foo");
        try {
        // do stuff
        } finally {
           UtilTimerStack.pop("bar");
        }
        

        (Thus if the push() and pop() operations do not occur in the same thread, the snapshots don't match and the class logs the "Unmatched Timer" error.)

      2. and the utilisation of the ProfilingProcessMonitor in Stash, which invoke the push / pop operations in different threads:
        ### push ### ssh-scm-request-handler ### SSH - git-receive-pack '/project_1/linux.git'
        ...
        ### push ### ssh-scm-request-handler ### Ticket com.atlassian.stash.throttle.ThrottleService.acquireTicket(String)
        ### pop  ### ssh-scm-request-handler ### Ticket com.atlassian.stash.throttle.ThrottleService.acquireTicket(String)
        ### push ### ssh-scm-request-handler ### /usr/local/bin/git receive-pack /Users/pepoirot/Dev/apps-home/stash-default/data/repositories/51
        ### pop  ### ExtProcess - IO Pump:thread-7 ### /usr/local/bin/git receive-pack /Users/pepoirot/Dev/apps-home/stash-default/data/repositories/51
        ### pop  ### ssh-scm-request-handler ### SSH - git-receive-pack '/project_1/linux.git'
        

      As seen above, the last push() occurs in the ssh-scm-request-handler while the corresponding pop() occurs in one of the process's IO pump in process-utils.

      After discussing with Charles O'Farrell [Atlassian], the problem seems to date back to at least Stash 2.0, when ProfilingProcessMonitor was introduced to replace the manual call in BaseCommand .

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              dkjellin Daniel Kjellin
              Reporter:
              pepoirot Pierre-Etienne Poirot (Inactive)
              Votes:
              2 Vote for this issue
              Watchers:
              11 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: