Skip to content

trace: fixes to help for heap allocation debugging #4548

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
lgirdwood merged 2 commits into from
Sep 16, 2021
Merged

trace: fixes to help for heap allocation debugging #4548

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
410ebe4
alloc: trace error when allocation failed with no condition
keyonjie Jul 26, 2021
47606c2
trace: Kconfig: disable filtering by default
keyonjie Jul 26, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
207 changes: 61 additions & 146 deletions src/lib/alloc.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -548,113 +548,88 @@ static void free_block(void *ptr)
#endif
}

#if CONFIG_DEBUG_HEAP

static void trace_heap_blocks(struct mm_heap *heap)
#if CONFIG_TRACE
void heap_trace(struct mm_heap *heap, int size)
{
struct block_map *block_map;
struct block_map *current_map;
int i;
int j;

tr_err(&mem_tr, "heap: 0x%x size %d blocks %d caps 0x%x", heap->heap,
heap->size, heap->blocks, heap->caps);
tr_err(&mem_tr, " used %d free %d", heap->info.used,
heap->info.free);
for (i = 0; i < size; i++) {
tr_info(&mem_tr, " heap: 0x%x size %d blocks %d caps 0x%x",
heap->heap, heap->size, heap->blocks,
heap->caps);
tr_info(&mem_tr, " used %d free %d", heap->info.used,
heap->info.free);

for (i = 0; i < heap->blocks; i++) {
block_map = &heap->map[i];
/* map[j]'s base is calculated based on map[j-1] */
for (j = 0; j < heap->blocks; j++) {
current_map = &heap->map[j];

tr_err(&mem_tr, " block %d base 0x%x size %d count %d", i,
block_map->base, block_map->block_size,
block_map->count);
tr_err(&mem_tr, " free %d first at %d",
block_map->free_count, block_map->first_free);
tr_info(&mem_tr, " block %d base 0x%x size %d",
j, current_map->base,
current_map->block_size);
tr_info(&mem_tr, " count %d free %d",
current_map->count,
current_map->free_count);
}

heap++;
}

}

static void alloc_trace_heap(enum mem_zone zone, uint32_t caps, size_t bytes)
void heap_trace_all(int force)
{
struct mm *memmap = memmap_get();
struct mm_heap *heap_base;
struct mm_heap *heap;
unsigned int heap_count;
unsigned int n;
unsigned int i = 0;
int count = 0;

switch (zone) {
case SOF_MEM_ZONE_SYS:
heap_base = memmap->system;
heap_count = PLATFORM_HEAP_SYSTEM;
break;
case SOF_MEM_ZONE_SYS_RUNTIME:
heap_base = memmap->system_runtime;
heap_count = PLATFORM_HEAP_SYSTEM_RUNTIME;
break;
case SOF_MEM_ZONE_RUNTIME:
heap_base = memmap->runtime;
heap_count = PLATFORM_HEAP_RUNTIME;
break;
case SOF_MEM_ZONE_BUFFER:
heap_base = memmap->buffer;
heap_count = PLATFORM_HEAP_BUFFER;
break;
/* has heap changed since last shown */
if (memmap->heap_trace_updated || force) {
tr_info(&mem_tr, "heap: system status");
heap_trace(memmap->system, PLATFORM_HEAP_SYSTEM);
tr_info(&mem_tr, "heap: system runtime status");
heap_trace(memmap->system_runtime, PLATFORM_HEAP_SYSTEM_RUNTIME);
tr_info(&mem_tr, "heap: buffer status");
heap_trace(memmap->buffer, PLATFORM_HEAP_BUFFER);
tr_info(&mem_tr, "heap: runtime status");
heap_trace(memmap->runtime, PLATFORM_HEAP_RUNTIME);
#if CONFIG_CORE_COUNT > 1
case SOF_MEM_ZONE_RUNTIME_SHARED:
heap_base = memmap->runtime_shared;
heap_count = PLATFORM_HEAP_RUNTIME_SHARED;
break;
case SOF_MEM_ZONE_SYS_SHARED:
heap_base = memmap->system_shared;
heap_count = PLATFORM_HEAP_SYSTEM_SHARED;
break;
#else
case SOF_MEM_ZONE_RUNTIME_SHARED:
heap_base = memmap->runtime;
heap_count = PLATFORM_HEAP_RUNTIME;
break;
case SOF_MEM_ZONE_SYS_SHARED:
heap_base = memmap->system;
heap_count = PLATFORM_HEAP_SYSTEM;
break;
tr_info(&mem_tr, "heap: runtime shared status");
heap_trace(memmap->runtime_shared, PLATFORM_HEAP_RUNTIME_SHARED);
tr_info(&mem_tr, "heap: system shared status");
heap_trace(memmap->system_shared, PLATFORM_HEAP_SYSTEM_SHARED);
#endif
default:
tr_err(&mem_tr, "alloc trace: unsupported mem zone");
goto out;
}
heap = heap_base;
n = heap_count;

while (i < heap_count) {
heap = get_heap_from_caps(heap, n, caps);
if (!heap)
break;

trace_heap_blocks(heap);
count++;
i = heap - heap_base + 1;
n = heap_count - i;
heap++;
}
memmap->heap_trace_updated = 0;

if (count == 0)
tr_err(&mem_tr, "heap: none found for zone %d caps 0x%x, bytes 0x%x",
zone, caps, bytes);
out:
return;
}
#else
void heap_trace_all(int force) { }
void heap_trace(struct mm_heap *heap, int size) { }
#endif

#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) \
if (trace_get()) { \
if (!ptr) { \
tr_err(&mem_tr, "failed to alloc 0x%x bytes zone 0x%x caps 0x%x flags 0x%x", \
bytes, zone, caps, flags); \
alloc_trace_heap(zone, caps, bytes); \
}
#define _ALLOC_FAILURE(bytes, zone, caps, flags) \
tr_err(&mem_tr, \
"failed to alloc 0x%x bytes zone 0x%x caps 0x%x flags 0x%x", \
bytes, zone, caps, flags)

#if CONFIG_DEBUG_HEAP
#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) do { \
if (trace_get()) { \
if (!(ptr)) \
_ALLOC_FAILURE(bytes, zone, caps, flags); \
heap_trace_all(0); \
} \
} while (0)
#else
#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags)
#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) do { \
if (trace_get()) { \
if (!(ptr)) { \
_ALLOC_FAILURE(bytes, zone, caps, flags); \
heap_trace_all(0); \
} \
} \
Copy link
Member

@lgirdwood lgirdwood Jul 26, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry, I was meaning from my comment on the previous PR it would be good to dump the heap blocks on any allocation error. I see we are already doing this but in debug mode only ?

Copy link
Contributor Author

@keyonjie keyonjie Jul 26, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry, I was meaning from my comment on the previous PR it would be good to dump the heap blocks on any allocation error. I see we are already doing this but in debug mode only ?

That's true. One more bad thing is that our trace are always filtered out by the trace filtering, that's why I tried to set the filtering to N by default

Copy link
Member

@lgirdwood lgirdwood Aug 3, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we do something like this (it sames duplicating the print).

#define _DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) \
	do { \
		if (!(ptr)) { \
			tr_err(&mem_tr, \
			       "failed to alloc 0x%x bytes zone 0x%x caps 0x%x flags 0x%x", \
			       bytes, zone, caps, flags); \
		} \
	} while (0)

#if DEBUG
#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) \
                       _DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) \
			alloc_trace_heap(zone, caps, bytes);
#else
#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) \
                       _DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags)
#endif

Copy link
Collaborator

@ranj063 ranj063 Aug 24, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it doesnt look like this feedback was addressed?

Copy link
Collaborator

@lyakh lyakh Aug 26, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes, definitely good to deduplicate, but can I propose a slight modification:

#define _DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) \
	if (!(ptr)) \
		tr_err(&mem_tr, \
		       "failed to alloc 0x%x bytes zone 0x%x caps 0x%x flags 0x%x", \
		       bytes, zone, caps, flags)
#if DEBUG
#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) do { \
	_DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags); \
	alloc_trace_heap(zone, caps, bytes); \
while (0)
#else
#define DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags) do { \
	_DEBUG_TRACE_PTR(ptr, bytes, zone, caps, flags); \
while (0)
#endif

to always have do { ... } while (0) externally

} while (0)
#endif

/* allocate single block for system runtime */
Expand Down Expand Up @@ -1084,66 +1059,6 @@ void free_heap(enum mem_zone zone)

}

#if CONFIG_TRACE
void heap_trace(struct mm_heap *heap, int size)
{
struct block_map *current_map;
int i;
int j;

for (i = 0; i < size; i++) {
tr_info(&mem_tr, " heap: 0x%x size %d blocks %d caps 0x%x",
heap->heap, heap->size, heap->blocks,
heap->caps);
tr_info(&mem_tr, " used %d free %d", heap->info.used,
heap->info.free);

/* map[j]'s base is calculated based on map[j-1] */
for (j = 0; j < heap->blocks; j++) {
current_map = &heap->map[j];

tr_info(&mem_tr, " block %d base 0x%x size %d",
j, current_map->base,
current_map->block_size);
tr_info(&mem_tr, " count %d free %d",
current_map->count,
current_map->free_count);
}

heap++;
}
}

void heap_trace_all(int force)
{
struct mm *memmap = memmap_get();

/* has heap changed since last shown */
if (memmap->heap_trace_updated || force) {
tr_info(&mem_tr, "heap: system status");
heap_trace(memmap->system, PLATFORM_HEAP_SYSTEM);
tr_info(&mem_tr, "heap: system runtime status");
heap_trace(memmap->system_runtime, PLATFORM_HEAP_SYSTEM_RUNTIME);
tr_info(&mem_tr, "heap: buffer status");
heap_trace(memmap->buffer, PLATFORM_HEAP_BUFFER);
tr_info(&mem_tr, "heap: runtime status");
heap_trace(memmap->runtime, PLATFORM_HEAP_RUNTIME);
#if CONFIG_CORE_COUNT > 1
tr_info(&mem_tr, "heap: runtime shared status");
heap_trace(memmap->runtime_shared, PLATFORM_HEAP_RUNTIME_SHARED);
tr_info(&mem_tr, "heap: system shared status");
heap_trace(memmap->system_shared, PLATFORM_HEAP_SYSTEM_SHARED);
#endif
}

memmap->heap_trace_updated = 0;

}
#else
void heap_trace_all(int force) { }
void heap_trace(struct mm_heap *heap, int size) { }
#endif

/* initialise map */
void init_heap(struct sof *sof)
{
Expand Down
6 changes: 3 additions & 3 deletions src/trace/Kconfig
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,22 +35,22 @@ config TRACEM
config TRACE_FILTERING
bool "Trace filtering"
depends on TRACE
default y
default n
Copy link
Collaborator

@marc-hb marc-hb Jul 27, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is hiding a very big change in a PR with a totally unrelated name.

Copy link
Contributor Author

@keyonjie keyonjie Jul 28, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do you mean the PR subject, let me rename it. Anyway, the change is mentioned in the commit subject.

Copy link
Collaborator

@marc-hb marc-hb Jul 28, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes the commit is fine, I was only referring to the PR name.

This relatively complex feature took a lot of effort, so I'm pretty sure it was developed for a reason. This change could kill performance on all production systems with just one character change. So even a scary PR name may not be enough, it should probably be discussed in some larger forum / mailing list.

Copy link
Contributor Author

@keyonjie keyonjie Jul 28, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes the commit is fine, I was only referring to the PR name.

This relatively complex feature took a lot of effort, so I'm pretty sure it was developed for a reason. This change could kill performance on all production systems with just one character change. So even a scary PR name may not be enough, it should probably be discussed in some larger forum / mailing list.

No, in real production systems, usually the DMA trace itself is disabled thoroughly, I don't think the feature is useful at all, please correct me if you think so.

Anyway, it filters out useful logs by mistake from time to time for me, it is legit to disable it by default to me.

Copy link
Member

@lgirdwood lgirdwood Jul 28, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The filtering is a useful developer debug feature, i.e. helps developers improve the trace SNR when debugging issues when there is high frequency trace output. However for CI usage it can hide some important details in the logs that would be useful for triage. I'm good to try this change for CI and see if it helps

Copy link
Contributor Author

@keyonjie keyonjie Sep 17, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I just change to unselect the whole TRACE_FILTERING feature, frankly speaking I don't know how to use the _TRACE_FILTERING_VERBOSITY at all, I haven't seen the tr_dbg() logs for years. @slawblauciak asked me about this and what I shared to him is just use tr_info() only.
@marc-hb can you share how should CI and customer use this _TRACE_FILTERING_VERBOSITY today? If nobody is using it, no harm to disable it by default, no?

Copy link
Member

@plbossart plbossart Sep 17, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@keyonjie I also disagree with your approach. Why wasn't this change a different PR? we could have fixed the 'filtering by mistake' instead of disabling the capability entirely.

@lgirdwood we need to keep the rule that there are TWO approvers on such critical PRs. This ignores feedback, it's not a good process.

Copy link
Collaborator

@marc-hb marc-hb Sep 20, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@marc-hb can you share how should CI and customer use this _TRACE_FILTERING_VERBOSITY today?

By following the official documentation:
https://thesofproject.github.io/latest/developer_guides/debugability/logger/index.html#trace-filtering

Filtering by log levels and component is really the most basic feature of any logging framework.

This commit apparently caused regression #4779 , according to some people reverting it seems to make the problem go away. Of course the code should in theory work with any Kconfig combination, I am not saying changing Kconfig is the root cause. But we need the tests to pass.

Because both, unrelated settings were changed in the same commit ("just in case?"), validation could not immediately find which one setting caused the regression.

Cc: @ranj063 , @1994lwz

Copy link
Collaborator

@marc-hb marc-hb Sep 21, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These KConfig changes have been reverted in #4785 because of regression #4779. @keyonjie I now understand that CONFIG_TRACE_FILTERING_ADAPTIVE is the only default you wanted to change, correct? Please re-submit with only the CONFIG_TRACE_FILTERING_ADAPTIVE default change (it's all very brittle, so only one change at a time) and after first thoroughly trying to reproduce issue #4779 locally.

Copy link
Collaborator

@marc-hb marc-hb Jan 6, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, it's very easy to turn off CONFIG_TRACE_FILTERING_ADAPTIVE at run-time, no recompilation needed: #5154

help
Filtering of trace messages based on their verbosity level and frequency.

config TRACE_FILTERING_VERBOSITY
bool "Filter by verbosity"
depends on TRACE_FILTERING
default y
default n
help
Filtering by log verbosity level, where maximum verbosity allowed is specified for each
context and may be adjusted in runtime.

config TRACE_FILTERING_ADAPTIVE
bool "Adaptive rate limiting"
depends on TRACE_FILTERING
default y
default n
help
Adaptive filtering of trace messages, tracking up to CONFIG_TRACE_RECENT_ENTRIES_COUNT,
suppressing all repeated messages for up to CONFIG_TRACE_RECENT_TIME_THRESHOLD cycles.
Expand Down