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

Feb 26 '20 15:02 subdiff

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%)`	:arrow_down:
output.c	`87.23% <84.00%> (-3.88%)`	:arrow_down:
alloc.c	`87.92% <100.00%> (+0.13%)`	:arrow_up:

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.

Feb 26 '20 15:02 codecov-io

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

Feb 28 '20 17:02 emersion

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

Mar 08 '20 21:03 emersion

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

Mar 08 '20 22:03 subdiff

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: https://github.com/emersion/libliftoff/commit/950e100d7ec268abce8acc73d1316aa58abd8db2

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?

Mar 10 '20 11:03 emersion

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.

Mar 11 '20 13:03 subdiff

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?

Mar 13 '20 23:03 emersion

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.

Mar 18 '20 01:03 subdiff

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)

Mar 24 '20 09:03 subdiff

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.

Mar 25 '20 16:03 emersion

Improve debug log

Codecov Report