Improve debug log #43

subdiff · 2020-02-26T15:43:07Z

Working on gamescope's usage of libliftoff I need to get good debug logs without too much output at once.

For that repetition of unchanging output is minimized and the format of important output is improved.

Example of the output of one call to liftoff_output_apply after this PR has been merged:

Apply on output 0x55c447db2b50.
Layers on CRTC 62:
  Layer 0x55c447db2a40:
    FB_ID = 108
    zpos = 0
    alpha = 65535
    SRC_X = 0
    SRC_Y = 0
    SRC_W = 3840
    SRC_H = 2160
    CRTC_X = 0
    CRTC_Y = 0
    CRTC_W = 3840
    CRTC_H = 2160
Disabling planes: 55 52 49 46 43 40 71 69 67 65 63 61 58
Performing allocation for plane 55 (1/13)
  Layer 0x55c447db2a40 -> plane 55: applying properties...
  Layer 0x55c447db2a40 -> plane 55: incompatible properties
Performing allocation for plane 61 (12/13)
  Layer 0x55c447db2a40 -> plane 61: applying properties...
  Layer 0x55c447db2a40 -> plane 61: incompatible properties
Performing allocation for plane 58 (13/13)
  Layer 0x55c447db2a40 -> plane 58: applying properties...
  Layer 0x55c447db2a40 -> plane 58: success
Found a better allocation with score=1
Found plane allocation for output 0x55c447db2b50 with score=1
Assigning layers to planes:
  Layer 0x55c447db2a40 -> plane 58

codecov-io · 2020-02-26T15:58:08Z

Codecov Report

Merging #43 into master will decrease coverage by 1.11%.
The diff coverage is 74.46%.

@@            Coverage Diff             @@
##           master      #43      +/-   ##
==========================================
- Coverage   81.92%   80.80%   -1.12%     
==========================================
  Files           7        7              
  Lines         603      693      +90     
==========================================
+ Hits          494      560      +66     
- Misses        109      133      +24

Impacted Files	Coverage Δ
log.c	`64.28% <57.89%> (-13.50%)`	⬇️
output.c	`87.23% <84.00%> (-3.88%)`	⬇️
alloc.c	`87.92% <100.00%> (+0.13%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 950e100...bb24849. Read the comment docs.

layer.c

output.c

emersion · 2020-02-27T17:55:56Z

alloc.c

 			    "applying properties...",
 			    (void *)layer, plane->id);
 		if (!plane_apply(plane, layer, result->req, &compatible)) {
 			return false;
 		}
 		if (!compatible) {
 			liftoff_log(LIFTOFF_DEBUG,
-				    "Layer %p -> plane %"PRIu32": "
+					"  Layer %p -> plane %"PRIu32": "


Nitpick: alignment is broken here

These tabs are killing me sometimes. I am using QtCreator and most of the time it seems to work fine after I configured it to use tabs. But sometimes the alignment breaks for unknown reasons. I can't find this alignment problem anymore in the current revision.

emersion · 2020-02-27T17:56:03Z

alloc.c

@@ -425,7 +425,7 @@ bool output_choose_layers(struct liftoff_output *output,
 		}
 		if (compatible) {
 			liftoff_log(LIFTOFF_DEBUG,
-				    "Layer %p -> plane %"PRIu32": success",
+					"  Layer %p -> plane %"PRIu32": success",


log.c

emersion · 2020-02-28T17:18:31Z

alloc.c

 	liftoff_list_for_each(plane, &device->planes, link) {
 		if (plane->layer == NULL) {
-			liftoff_log(LIFTOFF_DEBUG,
-				    "Disabling plane %"PRIu32, plane->id);
+			liftoff_log_cnt(LIFTOFF_DEBUG, " %"PRIu32, plane->id);


Hmm. I'm on the fence about this, I'm not a fan of adding a new log API, especially given that some log APIs aren't able to control whether newlines are added to the output or not. For instance this is the case of wlroots' log system.

if (log_has(LIFTOFF_DEBUG)) { char *buf = calloc(1, 11 * liftoff_list_length(&device->planes) + 1); size_t n = 0; liftoff_list_for_each(plane, &device->planes, link) { if (plane->layer == NULL) { int ret = snprintf(&buf[n], 12, " %"PRIu32, plane->id); if (ret < 0) { break; } n += ret - 1; } } liftoff_log(LIFTOFF_DEBUG, "Disabling planes:%s", buf); free(buf); } … // Proceed disabling the planes

Having a buffer though whenever a line is not meant to be output directly is super complicated though. :(

Is there not a more stream-like way to do that?

What could be an alternative is to have in the log.c file a single buffer that fills with liftoff_log_cnt and is reallocated when it becomes full. Finally it is prepended whenever liftoff_log is called.

I have uploaded a new patch where per-device log buffers are created for continuous debug messages. It's a bit more involved for what it's doing in the end but that way all memory management for debugging is in a single log function.

I have added the change as a new commit in the end but if you are ok with the solution I can also replace this earlier commit with it.

emersion · 2020-02-28T17:26:25Z

plane.c

@@ -30,6 +30,37 @@ static int guess_plane_zpos_from_type(struct liftoff_device *device,
 	return 0;
 }

+static void log_plane(struct liftoff_plane *plane)


Hmm. Maybe we can ask users to run drm_info if we need this kind of information?

I see your point though for rapid development at least short term it makes sense to keep it in. It gives a good overview of only the relevant parts of the system without the need for other tools.

It also logs the zpos value that is not always a drm property.

On the other side I have just added a commit that logs the current state of all relevant planes on apply on an output. So you get an overview there as well.

So I'm fine either way.

emersion · 2020-02-28T17:29:05Z

output.c

@@ -63,7 +66,15 @@ void output_log_layers(struct liftoff_output *output) {
 		return;
 	}

-	liftoff_log(LIFTOFF_DEBUG, "Layers on CRTC %"PRIu32":", output->crtc_id);
+	liftoff_log(LIFTOFF_DEBUG, "\n== Apply request for output %"PRIu32" ==", output->crtc_id);


I'd prefer not to add \n chars in logging output, because some loggers might add a prefix (with the current time for instance) and this would break it.

Ok, makes sense. But then I would try to expand the API as in communicating when a line should be kind of a "header". Otherwise the output is really difficult to read with all the layer and plane information.

See latest commit 6c1d2a1 with a proposal for such an API.

emersion · 2020-02-28T17:31:33Z

alloc.c

@@ -571,6 +571,58 @@ static void log_reuse(struct liftoff_output *output)
 	output->alloc_reuse++;
 }

+static void log_plane_type_change(uint32_t base, uint32_t cmp)


Not a fan of this commit. When a lot of planes are present most will have the "overlay" type. IMHO plane IDs should be enough (and drm_info can help if more info is needed).

Maybe I should just in general remove logging the planes being reset. It does not really give useful information besides a single output line with the ids of all planes on the system.

EDIT: ok it's a little bit more involved: it's all planes that are available for associating with a layer and are compatible with the output. I have to recheck that my latest commit does log all these correctly and then the information in the single line with is superfluous.

EDIT2: ok, it's even more involved. it's obviously not only planes compatible with the output. It is planes that were not associated with any layer at the start of apply or planes that had been but are compatible with the output.

emersion · 2020-02-28T17:32:15Z

On the whole this looks good, thanks for working on this!

emersion · 2020-03-08T21:36:10Z

I've merged the following commits with minor edits:

refactor: add log verbosity helper
feat: log reuse only on change
feat: log layer priority only on change
refactor: skip layer debug early
fix: respect implicit type on layer props log
feat: omit logging inactive layer information
feat: indent log on property applying and layer assignment

subdiff · 2020-03-08T22:09:08Z

Thanks, can I get some feedback on why the other commits weren't merged?

emersion · 2020-03-10T11:47:00Z

I rebased the remaining commits in this branch: https://github.com/emersion/libliftoff/tree/subdiff-log

The commits are untouched (ie. as close as possible to your version, just edited to make them build) and unreviewed. Feel free to check that I haven't messed anything up and start working again from there.

As a general note, in the future it would make it easier for reviewers if commits are self-contained and only do one thing. I understand I've given feedback so you need to change things, but a clean history is important (see https://gitlab.freedesktop.org/wayland/weston/-/blob/master/CONTRIBUTING.md). For instance in this PR a commit adds log_no_output, a subsequent commit removes it, and another subsequent commit adds it back. Also some commits contain unrelated minor changes (whitespace/formatting/etc).

To fix that, git commit -p, git commit --amend and git rebase -i are your friends. See https://git-rebase.io/.

Added an explicit section about contributing in the README: 950e100

Now some more specific comments about the remaining unmerged patches (https://github.com/emersion/libliftoff/compare/subdiff-log):

Style is still off: alignment needs to be fixed, lines shouldn't be longer than 80 chars. See Weston's style guide.
I'd still prefer not to have \n in debug messages.
I'd prefer not to add log sections or special formatting (LIFTOFF_LOG_SECTION_*). IMHO adds too much complexity. I don't want perfect logs, I want a good balance between log quality and complexity. Indentation should be enough.
I'd still prefer not to log all the planes on startup (the log_planes and log_plane functions). This is already covered by drm_info and the layer <-> plane mapping logs.
I'd try to avoid debug_cnt and debug_end. If we need to format a list of things on a single line only once or twice (only for logging the disabled planes?), I'd rather not add a special API for this. If we really need it in more places, we could add something among these lines: https://paste.sr.ht/%7Eemersion/21c7534b21ab088661d3f8e9c8400fdb510900d0
+1 for logging some light metadata about planes in liftoff_output_apply, like the plane type. It can simply be added to the Layer XXX -> plane YYY line, e.g. Layer 0x606000000200 -> plane 42 (primary).

What do you think?

subdiff · 2020-03-11T13:54:28Z

I'd still prefer not to have \n in debug messages.

I'd prefer not to add log sections or special formatting (LIFTOFF_LOG_SECTION_*). IMHO adds too much complexity. I don't want perfect logs, I want a good balance between log quality and complexity. Indentation should be enough.

Thought about this again and what I need is a way to separate one burst of information from another one (i.e. per frame). In the default log I just use an additional empty line. Could we not just do that: print out an empty line?

I'd still prefer not to log all the planes on startup (the log_planes and log_plane functions). This is already covered by drm_info and the layer <-> plane mapping logs.

Yea, as said I'm fine either way with the layer <-> plane logs in place. I will remove it.

I'd try to avoid debug_cnt and debug_end. If we need to format a list of things on a single line only once or twice (only for logging the disabled planes?), I'd rather not add a special API for this. If we really need it in more places, we could add something among these lines: https://paste.sr.ht/%7Eemersion/21c7534b21ab088661d3f8e9c8400fdb510900d0

Yea, that's nice. I will try it out.

+1 for logging some light metadata about planes in liftoff_output_apply, like the plane type. It can simply be added to the Layer XXX -> plane YYY line, e.g. Layer 0x606000000200 -> plane 42 (primary).

On apply it currently prints all properties of output-compatible planes (in a condensed form for non-active ones). I found this to be quite helpful when debugging the changes or non-changes of layers. I would recommend this over only printing the type even though it takes more space.

emersion · 2020-03-13T23:33:59Z

Thought about this again and what I need is a way to separate one burst of information from another one (i.e. per frame). In the default log I just use an additional empty line. Could we not just do that: print out an empty line?

This won't look good when interleaved with the compositor and/or other libraries' debug logs. The compositor can print whatever it wants between frames so that'd be a better place to do it I think.

This would allow for e.g.:

[gamescope] NEW FRAME #1234
[libliftoff] Computing plane allocation
[wlroots] Performing atomic commit

[gamescope] NEW FRAME #1235
[libliftoff] Computing plane allocation
[wlroots] Performing atomic commit

…

On apply it currently prints all properties of output-compatible planes (in a condensed form for non-active ones). I found this to be quite helpful when debugging the changes or non-changes of layers. I would recommend this over only printing the type even though it takes more space.

Wouldn't that just be the properties of the layers?

On apply log the type of planes in the final assignment for a direct overview of the result.

Logigng the list of planes being disabled at the beginning of an apply does not really give useful information. Planes are disabled (and by that become in theory ready for layer-assignment) if they do not have a layer associated at the moment or if they are compatible with the output. That is uninteresting since in this list the subset of planes that are compatible with the output stay constant. And while the subset of planes being reset not compatible with the output might vary from apply to apply it is also of less interest since by definition they are not compatible with what the apply is about.

This adds a buffer struct and some utility functions for continously logging into a small buffer. In the end the buffer is flushed as a single line to the specified log channel.

It is helpful for debugging to know in which state the available planes on an output are when a layout is applied that leads to a change. For that log all planes that are compatible with the output. Currently disabled planes have multiple properties logged per line to keep the log short.

subdiff · 2020-03-18T01:37:03Z

Thought about this again and what I need is a way to separate one burst of information from another one (i.e. per frame). In the default log I just use an additional empty line. Could we not just do that: print out an empty line?

This won't look good when interleaved with the compositor and/or other libraries' debug logs. The compositor can print whatever it wants between frames so that'd be a better place to do it I think.

This would allow for e.g.:
[gamescope] NEW FRAME #1234
[libliftoff] Computing plane allocation
[wlroots] Performing atomic commit

[gamescope] NEW FRAME #1235
[libliftoff] Computing plane allocation
[wlroots] Performing atomic commit

…

I have added some remaining commits. Not tested yet though.

On apply it currently prints all properties of output-compatible planes (in a condensed form for non-active ones). I found this to be quite helpful when debugging the changes or non-changes of layers. I would recommend this over only printing the type even though it takes more space.

Wouldn't that just be the properties of the layers?

They are the properties of the previous layer association if there was one. The problem is if you have for example the same layer association applied for a long time or a singular plane not associated for a long time and other debug output comes in between it is difficult to find in the log what the previous values were.

subdiff · 2020-03-24T09:57:12Z

I tested it now and it works fine:

Computing plane allocation on output 0x55fd5876d920
Planes on CRTC 62:
  Plane 55:
    type: primary
    FB_ID: 107
    IN_FENCE_FD: -1
    CRTC_ID: 62
    CRTC_X: 776
    CRTC_Y: 0
    CRTC_W: 2286
    CRTC_H: 2160
    SRC_X: 0
    SRC_Y: 0
    SRC_W: 1393
    SRC_H: 1316
    COLOR_ENCODING: 0
    COLOR_RANGE: 0

  Plane 61:
    type: cursor
    FB_ID: 100
    IN_FENCE_FD: -1
    CRTC_ID: 62
    CRTC_X: 1638
    CRTC_Y: 684
    CRTC_W: 48
    CRTC_H: 48
    SRC_X: 0
    SRC_Y: 0
    SRC_W: 48
    SRC_H: 48

  Plane 58 (inactive):
    type: overlay FB_ID: 0 IN_FENCE_FD: -1 CRTC_ID: 0
    CRTC_X: 0 CRTC_Y: 0 CRTC_W: 0 CRTC_H: 0
    SRC_X: 0 SRC_Y: 0 SRC_W: 0 SRC_H: 0
    alpha: 65535 pixel blend mode: 0

Available layers:
  Layer 0x55fd5876d810:
    FB_ID = 107
    zpos = 0
    SRC_X = 0
    SRC_Y = 0
    SRC_W = 1393
    SRC_H = 1316
    CRTC_X = 776
    CRTC_Y = 0
    CRTC_W = 2286
    CRTC_H = 2160
  Layer 0x55fd5876d700:
    FB_ID = 100
    zpos = 2
    SRC_X = 0
    SRC_Y = 0
    SRC_W = 48
    SRC_H = 48
    CRTC_X = 1638
    CRTC_Y = 686
    CRTC_W = 48
    CRTC_H = 48
Performing allocation for plane 55 (1/13)
  Layer 0x55fd5876d810 -> plane 55: applying properties...
  Layer 0x55fd5876d810 -> plane 55: success
Performing allocation for plane 61 (12/13)
  Layer 0x55fd5876d700 -> plane 61: applying properties...
  Layer 0x55fd5876d700 -> plane 61: success
Performing allocation for plane 58 (13/13)
Found a better allocation with score=1
  Layer 0x55fd5876d700 -> plane 55: applying properties...
  Layer 0x55fd5876d700 -> plane 55: success
Performing allocation for plane 61 (12/13)
Layer 0x55fd5876d810 -> plane 61: cannot put composition layer on non-primary plane
Performing allocation for plane 58 (13/13)
Layer 0x55fd5876d810 -> plane 58: cannot put composition layer on non-primary plane
Performing allocation for plane 61 (12/13)
Layer 0x55fd5876d810 -> plane 61: has composited layer on top
  Layer 0x55fd5876d700 -> plane 61: applying properties...
Found plane allocation for output 0x55fd5876d920 with score=1:
Final assignment of layers to planes:
  [1] Layer 0x55fd5876d810 -> plane 55 (primary)
  [2] Layer 0x55fd5876d700 -> plane 61 (cursor)

emersion · 2020-03-25T16:55:32Z

alloc.c

-		liftoff_log(LIFTOFF_DEBUG, "  Layer %p -> plane %"PRIu32,
-			    (void *)layer, plane->id);
+		j++;
+		liftoff_log(LIFTOFF_DEBUG, "  [%zu] Layer %p -> plane %"PRIu32


Does the j counter provide any useful information?

It just indexes the assignments. The question is if in the log at the end we should not compare j>0.

Ah, yeah, printing a message when no assignments are established seems like a good idea.

emersion · 2020-03-25T16:58:37Z

The last commit still sounds too involved. I don't want to maintain a KMS pretty-printer. The compositor can easily dump this information if it really wants to.

Otherwise the remaining commits look good.

subdiff force-pushed the log branch from 9668bb3 to 3eff252 Compare February 26, 2020 15:57

subdiff mentioned this pull request Feb 26, 2020

Clean up layering loop ValveSoftware/gamescope#29

Merged

subdiff force-pushed the log branch 2 times, most recently from 7c02655 to 4ff8682 Compare February 26, 2020 18:30

emersion reviewed Feb 27, 2020

View reviewed changes

layer.c Outdated Show resolved Hide resolved

emersion reviewed Feb 27, 2020

View reviewed changes

output.c Outdated Show resolved Hide resolved

emersion reviewed Feb 27, 2020

View reviewed changes

subdiff commented Feb 28, 2020

View reviewed changes

log.c Outdated Show resolved Hide resolved

emersion reviewed Feb 28, 2020

View reviewed changes

subdiff force-pushed the log branch 6 times, most recently from 6c1d2a1 to 7908175 Compare February 29, 2020 10:16

subdiff force-pushed the log branch from 7908175 to fa1c4e3 Compare March 18, 2020 01:28

romangg added 2 commits March 18, 2020 02:29

Log type of assigned planes

3cb6cd0

On apply log the type of planes in the final assignment for a direct overview of the result.

subdiff force-pushed the log branch from fa1c4e3 to bb24849 Compare March 18, 2020 01:32

romangg added 2 commits March 18, 2020 02:33

Add buffered log

82153bf

This adds a buffer struct and some utility functions for continously logging into a small buffer. In the end the buffer is flushed as a single line to the specified log channel.

emersion reviewed Mar 25, 2020

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve debug log #43

Improve debug log #43

subdiff commented Feb 26, 2020

codecov-io commented Feb 26, 2020 •

edited

Loading

emersion Feb 27, 2020

subdiff Feb 28, 2020

emersion Feb 27, 2020

emersion Feb 28, 2020

subdiff Feb 28, 2020

subdiff Feb 29, 2020

emersion Feb 28, 2020

subdiff Feb 28, 2020

emersion Feb 28, 2020 •

edited

Loading

subdiff Feb 28, 2020

subdiff Feb 29, 2020

emersion Feb 28, 2020

subdiff Feb 28, 2020 •

edited

Loading

emersion commented Feb 28, 2020

emersion commented Mar 8, 2020

subdiff commented Mar 8, 2020

emersion commented Mar 10, 2020

subdiff commented Mar 11, 2020 •

edited

Loading

emersion commented Mar 13, 2020 •

edited

Loading

subdiff commented Mar 18, 2020

subdiff commented Mar 24, 2020 •

edited

Loading

emersion Mar 25, 2020

subdiff Mar 25, 2020

emersion Mar 25, 2020

emersion commented Mar 25, 2020

Improve debug log #43

Are you sure you want to change the base?

Improve debug log #43

Conversation

subdiff commented Feb 26, 2020

codecov-io commented Feb 26, 2020 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

emersion Feb 28, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

subdiff Feb 28, 2020 • edited Loading

Choose a reason for hiding this comment

emersion commented Feb 28, 2020

emersion commented Mar 8, 2020

subdiff commented Mar 8, 2020

emersion commented Mar 10, 2020

subdiff commented Mar 11, 2020 • edited Loading

emersion commented Mar 13, 2020 • edited Loading

subdiff commented Mar 18, 2020

subdiff commented Mar 24, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

emersion commented Mar 25, 2020

codecov-io commented Feb 26, 2020 •

edited

Loading

emersion Feb 28, 2020 •

edited

Loading

subdiff Feb 28, 2020 •

edited

Loading

subdiff commented Mar 11, 2020 •

edited

Loading

emersion commented Mar 13, 2020 •

edited

Loading

subdiff commented Mar 24, 2020 •

edited

Loading