What might be causing repeated mmap/munmap in strace results

debuggingnode.jsstrace

I have a (node.js) application which is occasionally causing 100% CPU usage. I've attached to the process with strace when it's been in this state – but I don't know what to make if the strace output. The results repeat between these two patterns (shortened) :

mmap(0x30c3ac700000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x30c3ac700000
mmap(0x3364514ba000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x3364514ba000
munmap(0x3364514ba000, 286720)          = 0
munmap(0x336451600000, 761856)          = 0
mmap(0x336451500000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x336451500000
mmap(0x2b9c33880000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x2b9c33880000
munmap(0x2b9c33880000, 524288)          = 0
munmap(0x2b9c33a00000, 524288)          = 0
...

And…

munmap(0x2b9c33900000, 1048576)         = 0
munmap(0x336451500000, 1048576)         = 0
munmap(0x30c3ac700000, 1048576)         = 0
munmap(0x247e37500000, 1048576)         = 0
munmap(0x20d76c800000, 1048576)         = 0
munmap(0x1cae0d600000, 1048576)         = 0
munmap(0x163545100000, 1048576)         = 0
munmap(0x32dcfe700000, 1048576)         = 0
munmap(0x1a1feff00000, 1048576)         = 0
munmap(0x3fb72f00000, 1048576)          = 0
munmap(0x366536900000, 1048576)         = 0
...

Can anyone shed any light as to what might be going on here? Thank you!

Best Answer

All that can be deduced from this output is that the application is allocating and freeing memory. So there must be some data structures which are growing and shrinking.

That unfortunately doesn't say a lot about what is happening at a higher layer of the application.

We can also deduce something about how the memory management implementation in node.js is implemented since there are two different variations of the arguments for mmap.

PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE

These arguments allocate address space but PROT_NONE means the reserved address space cannot be used (unless another later call makes it accessible).

PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS

These arguments allocate actual memory for a specific range of addresses (which presumably was one previously allocate with the other combination of arguments) and turns it into a read/write region.

Why it does that we can guess from looking at this sequence of four system calls:

mmap(0x3364514ba000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x3364514ba000
munmap(0x3364514ba000, 286720)          = 0
munmap(0x336451600000, 761856)          = 0
mmap(0x336451500000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x336451500000

This allocates 2MB of address space. Then free the start and end of that address space and finally allocate 1MB of memory for the middle part of the allocated address space.

Effectively these four calls allocate 1MB of memory with an address aligned at a multiple of 1MB. So we are looking at a pattern that explicitly wants aligned addresses.

The later munmap calls simply free the 1MB chunks allocated previously. In particular I notice

munmap(0x336451500000, 1048576)         = 0

That free the 1MB chunk allocated in the above four system calls.

All of this probably isn't what you wanted to know. But unfortunately that is what can be deduced from the strace output, so you'll have to find other ways to find the information you really want to know.

You may be interested in this feature request for a signal to dump a stack trace, which presumably would be very useful to you right now.

Another possibility is to add more logging code to your application.

Related Topic