search

cloudfoundry / jvmkill

Terminate the JVM when resources are exhausted
Apache License 2.0
30 stars 11 forks source link

Possible to add more details to ResourceExhausted! log message? #10

Closed youngm closed 6 years ago

youngm commented 7 years ago

It appears that when my application runs out of memory I no longer get an Exception telling me I ran out of memory and what type of memory I ran out of. Instead all I see is: ERR ResourceExhausted! (1/0) with a memory dump leaving it as an exercise for the user to look through the memory information to see what resource was exhausted. This can be difficult with Loggregator's tendancy to mess up line orders.

Is jvmkill the one logging "ResourceExhausted!"? And if so would it be possible to provide more information about what resource it was that might have been exhausted? Extra credit if we could provide a hint of what config to increase avoid the error in the future if there is one?

nebhale commented 7 years ago

@glyn Doesn’t this commit already do this? @youngm Are you not seeing this extended log message or is it not sufficient for you?

glyn commented 7 years ago

@youngm You can obtain a java Exception by setting the kill threshold to a non-zero value. For instance, include count=1 in the jvmkill agent parameters. With that value of count, the first time the agent sees the resource exhaustion event, it will allow the JVM to continue, probably by throwing OutOfMemory. The second time around, the agent will kill the JVM (before it has had a chance to throw OutOfMemory).

Is jvmkill the one logging "ResourceExhausted!"? Yes, it is, but just before it does, it should also log "Resource exhaustion event:" along with an indication of whether the resource exhausted was heap or thread. Is this appearing further down your log stream, thanks to Loggregator?

If it's not present, please could you provide the full logs so I can see what is present. Also, please check you are running with a fairly recent version of jvmkill. As @nebhale pointed out, the logging of "Resource exhaustion event:" plus details was implemented in mid June.

Finer detail of the memory pool state is provided in the "dump". It would be quite a major change to try to detect the specific memory pool, if any, which gave rise to the resource exhaustion event as this isn't handed to us on a plate by JVMTI. Please note also that we deliberately "pace" our log output, for example here, to reduce the probability of Loggregator shuffling it. If this isn't working, we might need to further decrease the rate of logging.

youngm commented 7 years ago

Thanks @glyn I'll take a closer look and see if I can identify the "Resource exhaustion event" as well and reopen if I don't see it. As far as logging the type of memory I think just giving the user whatever info you can easily acquire is good enough. Which it sounds like you're already doing that. I'll reopen if I have any trouble with that.

glyn commented 7 years ago

Thanks @youngm!

glyn commented 7 years ago

A follow-on issue to improve the diagnostics: https://github.com/cloudfoundry/jvmkill/issues/12.

glyn commented 6 years ago

Re-opening thanks to further analysis from @youngm:

I did some OOM testing and discovered that when Heap runs out I do see a "Resource exhaustion event" message. However, if I run out of MetaSpace or CompressedClassSpaceSize The only message I see in the logs is the: ResourceExhausted! (1/0) log line.

glyn commented 6 years ago

The JVM passes a flags parameter to jvmkills resource exhaustion exit with the following bits defined by the JVMTI spec:

JVMTI_RESOURCE_EXHAUSTED_OOM_ERROR | 0x0001 | After this event returns, the VM will throw a java.lang.OutOfMemoryError.
JVMTI_RESOURCE_EXHAUSTED_JAVA_HEAP | 0x0002 | The VM was unable to allocate memory from the JavaTM platform heap. The heap is the runtime data area from which memory for all class instances and arrays are allocated.
JVMTI_RESOURCE_EXHAUSTED_THREADS | 0x0004 | The VM was unable to create a thread.

It seems that none of these flags are set when metaspace or compressed class space is exhausted. Previously I had thought that JVMTI_RESOURCE_EXHAUSTED_JAVA_HEAP would be set in that case. I will change jvmkill to issue a resource exhaustion event message when none of the bits are set.

glyn commented 6 years ago

Fixed, including unit tests that the correct message comes out depending on the flags.