| Message ID | 20180731070527.17632-1-oohall@gmail.com |
|---|---|
| State | Accepted |
| Headers | show |
| Series | [v2] mem_region: Merge similar allocations when dumping | expand |
| Context | Check | Description |
|---|---|---|
| snowpatch_ozlabs/apply_patch | success | master/apply_patch Successfully applied |
| snowpatch_ozlabs/make_check | success | Test make_check on branch master |
"Oliver O'Halloran" <oohall@gmail.com> writes: > Currently we print one line for each allocation done at runtime when > dumping the memory allocations. We do a few thousand allocations at > boot so this can result in a huge amount of text being printed which > is a) slow to print, and b) Can result in the log buffer overflowing > which destroys otherwise useful information. > > This patch adds a de-duplication to this memory allocation dump by > merging "similar" allocations (same location, same size) into one. > > Unfortunately, the algorithm used to do the de-duplication is quadratic, > but considering we only dump the allocations in the event of a fatal > error I think this is acceptable. I also did some benchmarking and found > that on a ZZ it takes ~3ms to do a dump with 12k allocations. On a Zaius > it's slightly longer at about ~10ms for 10k allocs. However, the > difference there was due to the output being written to the UART. > > This patch also bumps the log level to PR_NOTICE. PR_INFO messages are > suppressed at the default log level, which probably isn't something you > want considering we only dump the allocations when we run out of skiboot > heap space. > > Signed-off-by: Oliver O'Halloran <oohall@gmail.com> > --- > v2: Only perform the dump on the first allocation failure rather > than every time. This allows us to extract useful debug information > when there is an allocation failure without spamming the console > too much. > > Fixed some 80 cols junk. > --- > core/mem_region.c | 49 ++++++++++++++++++++++++++++++++++++++++++------- > 1 file changed, 42 insertions(+), 7 deletions(-) cheers. Merged to master as of 55cab51c74a8a6c5bb2e298e541ab125c5ade553. Now I just need to run out of memory somewhere at some point so I can enjoy the great glory of slightly better terribleness.
diff --git a/core/mem_region.c b/core/mem_region.c index 0051ea6ece61..bd387f3c3773 100644 --- a/core/mem_region.c +++ b/core/mem_region.c @@ -96,7 +96,8 @@ static struct mem_region skiboot_cpu_stacks = { struct alloc_hdr { bool free : 1; bool prev_free : 1; - unsigned long num_longs : BITS_PER_LONG-2; /* Including header. */ + bool printed : 1; + unsigned long num_longs : BITS_PER_LONG-3; /* Including header. */ const char *location; }; @@ -285,7 +286,7 @@ static bool region_is_reserved(struct mem_region *region) void mem_dump_allocs(void) { struct mem_region *region; - struct alloc_hdr *hdr; + struct alloc_hdr *h, *i; /* Second pass: populate property data */ prlog(PR_INFO, "Memory regions:\n"); @@ -301,11 +302,40 @@ void mem_dump_allocs(void) prlog(PR_INFO, " no allocs\n"); continue; } - for (hdr = region_start(region); hdr; hdr = next_hdr(region, hdr)) { - if (hdr->free) + + /* + * XXX: When dumping the allocation list we coalase allocations + * with the same location and size into a single line. This is + * quadratic, but it makes the dump human-readable and the raw + * dump sometimes causes the log buffer to wrap. + */ + for (h = region_start(region); h; h = next_hdr(region, h)) + h->printed = false; + + for (h = region_start(region); h; h = next_hdr(region, h)) { + unsigned long bytes; + int count = 0; + + if (h->free) continue; - prlog(PR_INFO, " 0x%.8lx %s\n", hdr->num_longs * sizeof(long), - hdr_location(hdr)); + if (h->printed) + continue; + + for (i = h; i; i = next_hdr(region, i)) { + if (i->free) + continue; + if (i->num_longs != h->num_longs) + continue; + if (strcmp(i->location, h->location)) + continue; + + i->printed = true; + count++; + } + + bytes = h->num_longs * sizeof(long); + prlog(PR_NOTICE, " % 8d allocs of 0x%.8lx bytes at %s (total 0x%lx)\n", + count, bytes, hdr_location(h), bytes * count); } } } @@ -439,6 +469,7 @@ found: void *mem_alloc(struct mem_region *region, size_t size, size_t align, const char *location) { + static bool dumped = false; void *r; assert(lock_held_by_me(®ion->free_list_lock)); @@ -449,7 +480,11 @@ void *mem_alloc(struct mem_region *region, size_t size, size_t align, prerror("mem_alloc(0x%lx, 0x%lx, \"%s\", %s) failed !\n", size, align, location, region->name); - mem_dump_allocs(); + if (!dumped) { + mem_dump_allocs(); + dumped = true; + } + return NULL; }
Currently we print one line for each allocation done at runtime when dumping the memory allocations. We do a few thousand allocations at boot so this can result in a huge amount of text being printed which is a) slow to print, and b) Can result in the log buffer overflowing which destroys otherwise useful information. This patch adds a de-duplication to this memory allocation dump by merging "similar" allocations (same location, same size) into one. Unfortunately, the algorithm used to do the de-duplication is quadratic, but considering we only dump the allocations in the event of a fatal error I think this is acceptable. I also did some benchmarking and found that on a ZZ it takes ~3ms to do a dump with 12k allocations. On a Zaius it's slightly longer at about ~10ms for 10k allocs. However, the difference there was due to the output being written to the UART. This patch also bumps the log level to PR_NOTICE. PR_INFO messages are suppressed at the default log level, which probably isn't something you want considering we only dump the allocations when we run out of skiboot heap space. Signed-off-by: Oliver O'Halloran <oohall@gmail.com> --- v2: Only perform the dump on the first allocation failure rather than every time. This allows us to extract useful debug information when there is an allocation failure without spamming the console too much. Fixed some 80 cols junk. --- core/mem_region.c | 49 ++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 42 insertions(+), 7 deletions(-)