Hi Kirk, thanks for the response. I've run the same workload with -XX:+KeepSafepointsInCountedLoops, and the problem persists, so I'm fairly certain it's not that (assuming the JVM is respecting the flags...). The application is GC-free, so the safepoints are only going to be coming from (non-exhaustive): guaranteed safepoints, JIT operation?, lock biasing, others?
The environment is indeed toxic: multiple JVMs mmap files on the order of 1/4 system memory, performing either read or write operations and the page-cache flusher threads are struggling to cope (not surprisingly). I don't really want to go down the route of using madvise/mlock. Happily, this is a test environment, so I can be brave with profiling - what sort of instrumentation do you refer to - kernel jprobes or JVM hacking? Cheers, Mark On Tue, Dec 5, 2017 at 11:11 AM Kirk Pepperdine <[email protected]> wrote: > Hi, > > > On Dec 5, 2017, at 11:53 AM, Gil Tene <[email protected]> wrote: > > Page faults in mapped file i/o and counted loops are certainly two common > causes of long TTSP. But there are many other paths that *could* cause it > as well in HotSpot. Without catching it and looking at the stack trace, > it's hard to know which ones to blame. Once you knock out one cause, you'll > see if there is another. > > In the specific stack trace you showed [assuming that trace was taken > during a long TTSP], mapped file i/o is the most likely culprit. Your trace > seems to be around making the page write-able for the first time and > updating the file time (which takes a lock), but even without needing the > lock, the fault itself could end up waiting for the i/o to complete (read > page from disk), and that (when Murh=phy pays you a visit) can end up > waiting behind 100s other i/o operations (e.g. when your i/o happens at the > same time the kernel decided to flush some dirty pages in the cache), > leading to TTSPs in the 100s of msec. > > As I'm sure you already know, one simple way to get around mapped file > related TTSP is to not used mapped files. Explicit random i/o calls are > always done while at a safepoint, so they can't cause high TTSPs. > > > I guess another way to avoid the long TTSP is to not safe point.. ;-) > > Most of the long TTSP’s IME are either due to outside scheduling > interference or loops that are compiled to the point where they turn into > counted loops. Finding this using traditional tooling is impossible because > you need the safe point which has most likely been compiled out of the code > to get a sample to see why you’re waiting for a safe point. Using an async > profiler (like honest) leaves you wanting for some correlation between > calls for safe point and the samples you’re looking at. So, I don’t really > have a good answer as to how to find these things. What I have done in the > past is used the GC log to get an idea of the toxicity level of the > environment you’re running in and then use that information to decide if I > need to look for internal or external causes. If the causes are internal > than it’s most likely a counted loop. Using JITWatch in this cause can you > get a candidate list of counted loops to consider. After that I’ve binary > searched through that list. If the environment is toxic.. then you need to > clean up the environment. If you are brave, you add some instrumentation to > the JVM to sample for the last thread to reach the safe point and use that > in your prod environment. > > Kind regards, > Kirk > > > On Tuesday, December 5, 2017 at 10:30:57 AM UTC+1, Mark Price wrote: >> >> Hi Aleksey, >> thanks for the response. The I/O is definitely one problem, but I was >> trying to figure out whether it was contributing to the long TTSP times, or >> whether I might have some code that was misbehaving (e.g. NonCountedLoops). >> >> Your response aligns with my guesswork, so hopefully I just have the one >> problem to solve ;) >> >> >> >> Cheers, >> >> Mark >> >> On Tuesday, 5 December 2017 09:24:33 UTC, Aleksey Shipilev wrote: >>> >>> On 12/05/2017 09:26 AM, Mark Price wrote: >>> > I'm investigating some long time-to-safepoint pauses in >>> oracle/openjdk. The application in question >>> > is also suffering from some fairly nasty I/O problems where >>> latency-sensitive threads are being >>> > descheduled in uninterruptible sleep state due to needing a >>> file-system lock. >>> > >>> > My question: can the JVM detect that a thread is in >>> signal/interrupt-handler code and thus treat it >>> > as though it is at a safepoint (as I believe happens when a thread is >>> in native code via a JNI call)? >>> > >>> > For instance, given the stack trace below, will the JVM need to wait >>> for the thread to be scheduled >>> > back on to CPU in order to come to a safepoint, or will it be treated >>> as "in-native"? >>> > >>> > 7fff81714cd9 __schedule ([kernel.kallsyms]) >>> > 7fff817151e5 schedule ([kernel.kallsyms]) >>> > 7fff81717a4b rwsem_down_write_failed ([kernel.kallsyms]) >>> > 7fff813556e7 call_rwsem_down_write_failed ([kernel.kallsyms]) >>> > 7fff817172ad down_write ([kernel.kallsyms]) >>> > 7fffa0403dcf xfs_ilock ([kernel.kallsyms]) >>> > 7fffa04018fe xfs_vn_update_time ([kernel.kallsyms]) >>> > 7fff8122cc5d file_update_time ([kernel.kallsyms]) >>> > 7fffa03f7183 xfs_filemap_page_mkwrite ([kernel.kallsyms]) >>> > 7fff811ba935 do_page_mkwrite ([kernel.kallsyms]) >>> > 7fff811bda74 handle_pte_fault ([kernel.kallsyms]) >>> > 7fff811c041b handle_mm_fault ([kernel.kallsyms]) >>> > 7fff8106adbe __do_page_fault ([kernel.kallsyms]) >>> > 7fff8106b0c0 do_page_fault ([kernel.kallsyms]) >>> > 7fff8171af48 page_fault ([kernel.kallsyms]) >>> > ---- java stack trace ends here ---- >>> >>> I am pretty sure out-of-band page fault in Java thread does not yield a >>> safepoint. At least because >>> safepoint polls happen at given location in the generated code, because >>> we need the pointer map as >>> the part of the machine state, and that is generated by Hotspot (only) >>> around the safepoint polls. >>> Page faulting on random read/write insns does not have that luxury. Even >>> if JVM had intercepted that >>> fault, there is not enough metadata to work on. >>> >>> The stacktrace above seems to say you have page faulted and this >>> incurred disk I/O? This is >>> swapping, I think, and all performance bets are off at that point. >>> >>> Thanks, >>> -Aleksey >>> >>> > -- > > You received this message because you are subscribed to the Google Groups > "mechanical-sympathy" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to [email protected]. > > > For more options, visit https://groups.google.com/d/optout. > > -- > You received this message because you are subscribed to a topic in the > Google Groups "mechanical-sympathy" group. > To unsubscribe from this topic, visit > https://groups.google.com/d/topic/mechanical-sympathy/tepoA7PRFRU/unsubscribe > . > To unsubscribe from this group and all its topics, send an email to > [email protected]. > For more options, visit https://groups.google.com/d/optout. > -- You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. For more options, visit https://groups.google.com/d/optout.
