Uploaded image for project: 'Bitbucket Data Center'
  1. Bitbucket Data Center
  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 cofarrell, 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

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

              Dates

                Created:
                Updated:
                Resolved: