Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8132849

Increased stop time in cleanup phase because of single-threaded walk of thread stacks in NMethodSweeper::mark_active_nmethods()

    Details

    • Subcomponent:
    • Introduced In Version:
      8
    • CPU:
      generic
    • OS:
      generic

      Description

      One of our services that runs with a few thousand threads recently noticed an increase in safepoint stop times, but not gc times, upon transitioning to JDK 8 from JDK 7.

      Further investigation revealed that most of the delta was related to the so-called pre-gc/vm-op "cleanup" phase when various book-keeping activities are performed, and more specifically in the portion that walks java thread stacks single-threaded (!) and updates the hotness counters for the active nmethods. This code appears to
      be new to JDK 8 (in jdk 7 one would walk the stacks only during code cache sweeps).

      This code should be fixed by either:
      (a) doing these updates by walking thread stacks in multiple worker threads in parallel, or best of all:
      (b) doing these updates when we walk the thread stacks during GC, and skipping this phase entirely
            for non-GC safepoints (with attendant loss in frequency of this update in low GC frequency
            scenarios).

      I also wonder how code cache sweep/eviction quality might be compromised if one were to do these hotness updates at a much lower frequency, as a temporary workaround to the performance problem.

      This issue was discussed at some length on the hotspot-compiler-dev@openjdk.java.net mailing list in the thread starting at:

             http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2015-July/018618.html

      where further detail can be obtained.

      The same issue exists in JDK 9, but not in JDK 7.

      More specifically, as stated in one of the email messages in that thread:

      ''
      I noticed the increase even with Initial and Reserved set to the default of 240 MB, but actual usage much lower (less than a quarter).

      Look at this code path. Note that this is invoked at every safepoint (although it says "periodically" in the comment). In the mark_active_nmethods() method, there's a thread iteration in both branches of the if.
      ....
      PS: for comparison, here's data with +TraceSafepointCleanup from JDK 7 (first, where this isn't done)
      vs JDK 8 (where this is done) with a program that has a few thousands of threads:



      JDK 7:
      ...
      2827.308: [sweeping nmethods, 0.0000020 secs]
      2828.679: [sweeping nmethods, 0.0000030 secs]
      2829.984: [sweeping nmethods, 0.0000030 secs]
      2830.956: [sweeping nmethods, 0.0000030 secs]
      ...

      JDK 8:
      ...
      7368.634: [mark nmethods, 0.0177030 secs]
      7369.587: [mark nmethods, 0.0178305 secs]
      7370.479: [mark nmethods, 0.0180260 secs]
      7371.503: [mark nmethods, 0.0186494 secs]
      ...
      Here's a snapshot of the code cache related counters:

      sun.ci.codeCacheCapacity=251658240
      sun.ci.codeCacheMaxCapacity=251658240
      sun.ci.codeCacheMethodsReclaimedNum=3450
      sun.ci.codeCacheSweepsTotalNum=58
      sun.ci.codeCacheSweepsTotalTimeMillis=1111
      sun.ci.codeCacheUsed=35888704

      Notice that the code cache usage is less that 35 MB, for the 240 MB capacity, yet it seems we have had 58 sweeps already, and safepoint cleanup says:

      [mark nmethods, 0.0165062 secs]

      Even if the two closures do little or no work, the single-threaded walk over deep stacks of a thousand threads will cost time for applications with many threads, and this is now done at each safepoint irrespective of the sweeper activity as far as I can tell. It seems as if this work should be somehow rolled up (via a suitable injection) into GC's thread walks that are done in parallel, rather than doing this in a pre-GC phase (unless I am mssing some reason that the sequencing is necessary, which it doesn't seem to be here).
      ''


      // Scans the stacks of all Java threads and marks activations of not-entrant methods.
      // No need to synchronize access, since 'mark_active_nmethods' is always executed at a
      // safepoint.
      void NMethodSweeper::mark_active_nmethods() {
        assert(SafepointSynchronize::is_at_safepoint(), "must be executed at a safepoint");
        // If we do not want to reclaim not-entrant or zombie methods there is no need
        // to scan stacks
        if (!MethodFlushing) {
          return;
        }

        // Increase time so that we can estimate when to invoke the sweeper again.
        _time_counter++;

        // Check for restart
        assert(CodeCache::find_blob_unsafe(_current) == _current, "Sweeper nmethod cached state invalid");
        if (!sweep_in_progress()) {
          _seen = 0;
          _sweep_fractions_left = NmethodSweepFraction;
          _current = CodeCache::first_nmethod();
          _traversals += 1;
          _total_time_this_sweep = Tickspan();

          if (PrintMethodFlushing) {
            tty->print_cr("### Sweep: stack traversal %d", _traversals);
          }
          Threads::nmethods_do(&mark_activation_closure);

        } else {
          // Only set hotness counter
          Threads::nmethods_do(&set_hotness_closure);
        }

        OrderAccess::storestore();
      }

        Activity

        Hide
        dpochepk Dmitrij Pochepko (Inactive) added a comment -
        ILW = performance regression; always; none = MHH = P2
        Show
        dpochepk Dmitrij Pochepko (Inactive) added a comment - ILW = performance regression; always; none = MHH = P2
        Hide
        thartmann Tobias Hartmann added a comment -
        The code cache sweeper scans thread stacks and performs one of the following two tasks at safepoints in NMethodSweeper::mark_active_nmethods():
        1) Searching for activations of non-entrant methods (see MarkActivationClosure) to avoid converting active nmethods to zombie state
        2) Resetting the hotness counter of methods being active on the stack (see SetHotnessClosure)

        Task 1) is only performed between sweeper cycles and is already included in JDK 7. The second task was introduced in JDK 8 by JDK-8020151 [1] which added a method hotness counter (nmethod::_hotness_counter) that is decremented if the nmethod is not found on the stack during scanning. This was necessary to fix severe performance regressions due to inefficient sweeping when the code cache fills up. See old discussion on hotspot-compiler-dev [2]:
        "There can be large performance regressions when the code cache fills up. There are several reasons for the performance regression: First (1), when the code cache is full and methods are speculatively disconnected, the oldest methods (based on compilation ID) are scheduled for flushing. This can result in flushing hot methods. Second (2), when compilation is disabled due to a full code cache, the number of sweeps can go down. A lower number of sweep operations results in slower method flushing."

        Removing task 2) will re-introduce these regressions but, as mentioned in the bug description, there are some possible solutions that would reduce the impact on applications with a large number of threads:
        (a) parallelize stack scanning
        (b) move stack scanning into GC (merge with existing stack scanning)
        (c) don't scan stacks of all the threads at a single safepoint but distribute work over multiple safepoints
        (d) only use hotness counters if the code cache fills up

        All of these need careful investigation to not re-introduce the regressions fixed by JDK-8020151. Especially, (b) may not scan the stacks often enough in low GC frequency scenarios causing hot nmethods to be flushed.

        [1] http://hg.openjdk.java.net/hsx/hsx25/hotspot/rev/510fbd28919c
        [2] http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2013-September/011588.html
        Show
        thartmann Tobias Hartmann added a comment - The code cache sweeper scans thread stacks and performs one of the following two tasks at safepoints in NMethodSweeper::mark_active_nmethods(): 1) Searching for activations of non-entrant methods (see MarkActivationClosure) to avoid converting active nmethods to zombie state 2) Resetting the hotness counter of methods being active on the stack (see SetHotnessClosure) Task 1) is only performed between sweeper cycles and is already included in JDK 7. The second task was introduced in JDK 8 by JDK-8020151 [1] which added a method hotness counter (nmethod::_hotness_counter) that is decremented if the nmethod is not found on the stack during scanning. This was necessary to fix severe performance regressions due to inefficient sweeping when the code cache fills up. See old discussion on hotspot-compiler-dev [2]: "There can be large performance regressions when the code cache fills up. There are several reasons for the performance regression: First (1), when the code cache is full and methods are speculatively disconnected, the oldest methods (based on compilation ID) are scheduled for flushing. This can result in flushing hot methods. Second (2), when compilation is disabled due to a full code cache, the number of sweeps can go down. A lower number of sweep operations results in slower method flushing." Removing task 2) will re-introduce these regressions but, as mentioned in the bug description, there are some possible solutions that would reduce the impact on applications with a large number of threads: (a) parallelize stack scanning (b) move stack scanning into GC (merge with existing stack scanning) (c) don't scan stacks of all the threads at a single safepoint but distribute work over multiple safepoints (d) only use hotness counters if the code cache fills up All of these need careful investigation to not re-introduce the regressions fixed by JDK-8020151. Especially, (b) may not scan the stacks often enough in low GC frequency scenarios causing hot nmethods to be flushed. [1] http://hg.openjdk.java.net/hsx/hsx25/hotspot/rev/510fbd28919c [2] http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2013-September/011588.html
        Hide
        thartmann Tobias Hartmann added a comment - - edited
        Justification for deferral to JDK 10: Performance problem for applications with a large number of threads due to increased safepoint pause time. This was introduced in JDK 8 by JDK-8020151 (see detailed analysis in my last comment). Fixing this is complex and requires a careful analysis to not re-introduce the original regressions. The fix potentially affects multiple components (compiler, runtime and GC) with a high risk of introducing a bug tail. Such nmethod sweeper bugs are hard to detect and fix. We should defer this high-risk fix to JDK 10 and backport the fix when it proved to be stable.
        Show
        thartmann Tobias Hartmann added a comment - - edited Justification for deferral to JDK 10: Performance problem for applications with a large number of threads due to increased safepoint pause time. This was introduced in JDK 8 by JDK-8020151 (see detailed analysis in my last comment). Fixing this is complex and requires a careful analysis to not re-introduce the original regressions. The fix potentially affects multiple components (compiler, runtime and GC) with a high risk of introducing a bug tail. Such nmethod sweeper bugs are hard to detect and fix. We should defer this high-risk fix to JDK 10 and backport the fix when it proved to be stable.

          People

          • Assignee:
            thartmann Tobias Hartmann
            Reporter:
            ysr Y. Ramakrishna
          • Votes:
            0 Vote for this issue
            Watchers:
            8 Start watching this issue

            Dates

            • Created:
              Updated: