Floor timestamp to the second when displaying age

[tobast]

This fixes the issue discussed in #1102; however, profiling shows that this is not the only performance problem when many notifications are active at once — which happens if eg. the computer is left unattended for a long time with idle_threshold > 0.

[fwsmit]

Thanks for taking a look at the issue! It seems like this is more a workaround for the bug. Dunst should not redraw the notification when the age is a millisecond different. Is it possible to fix it at the point where age value is checked?
It would also be nice to have a test to prevent this or similar errors in the future.

profiling shows that this is not the only performance problem when many notifications are active at once

Where are some other areas for improvement?

[codecov-commenter]

Codecov Report

Merging #1140 (95ef6d5) into master (7bd8e6b) will increase coverage by 0.12%.
The diff coverage is 86.20%.

📣 This organization is not using Codecov’s GitHub App Integration. We recommend you install it so Codecov can continue to function properly for your repositories. Learn more

@@            Coverage Diff             @@
##           master    #1140      +/-   ##
==========================================
+ Coverage   65.96%   66.09%   +0.12%     
==========================================
  Files          46       46              
  Lines        7548     7588      +40     
==========================================
+ Hits         4979     5015      +36     
- Misses       2569     2573       +4     

Flag	Coverage Δ
unittests	66.09% <86.20%> (+0.12%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
src/dunst.c	10.74% <0.00%> (-0.37%)	⬇️
src/notification.c	60.61% <0.00%> (ø)
src/queues.c	92.01% <100.00%> (+0.02%)	⬆️
test/queues.c	98.97% <100.00%> (+0.05%)	⬆️

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

[tobast]

Thanks for taking a look at the issue! It seems like this is more a workaround for the bug. Dunst should not redraw the notification when the age is a millisecond different. Is it possible to fix it at the point where age value is checked?

I have not gone into the details of what happens during a refresh, but the main problem here seems that if there are eg. 200 notifications, Dunst will be awoken in average once every 5ms. Whether the refresh stack is fast or not, 5ms is a very short timespan; if it takes eg. 2ms of boilerplate and pretty much nothing of actual refresh, this still makes for 40% CPU usage (2ms work every 5ms). Thus, it seems to me that it is crucial not to wake Dunst this often.

It would also be nice to have a test to prevent this or similar errors in the future.

Agreed. I don't see easily how that would be a unit test, though.

profiling shows that this is not the only performance problem when many notifications are active at once

Where are some other areas for improvement?

When profiling (with this patch applied) using

$ perf record -g ./dunst

and stress-testing with

$  for i in $(seq 1 200); do notify-send "Test $i" "Test"; done

while notification_limit is not set in the configuration, and show_age_threshold is set to a low value (eg. 5), perf report shows that

  Children      Self  Command         Shared Object                   Symbol                                                                                                                                                                                                     
-   69.11%     0.05%  dunst           dunst                           [.] draw                                                                                                                                                                                                  ◆
   - 69.06% draw                                                                                                                                                                                                                                                                ▒
      - 39.08% layout_render                                                                                                                                                                                                                                                    ▒
         - 31.90% render_content                                                                                                                                                                                                                                                ▒
            - 12.68% layout_get_height                                                                                                                                                                                                                                          ▒
               + 12.60% get_text_size                                                                                                                                                                                                                                           ▒
            + 11.48% pango_cairo_show_layout                                                                                                                                                                                                                                    ▒
            + 4.99% layout_setup                                                                                                                                                                                                                                                ▒
            + 0.91% g_log                                                                                                                                                                                                                                                       ▒
            + 0.58% cairo_fill                                                                                                                                                                                                                                                  ▒
         + 4.51% x_get_scale                                                                                                                                                                                                                                                    ▒
         + 1.98% render_background                                                                                                                                                                                                                                              ▒
      - 21.39% calculate_dimensions                                                                                                                                                                                                                                             ▒
         - 20.10% calculate_notification_dimensions                                                                                                                                                                                                                             ▒
            + 15.41% get_text_size                                                                                                                                                                                                                                              ▒
            + 4.57% layout_setup                                                                                                                                                                                                                                                ▒
         + 1.04% g_log                                                                                                                                                                                                                                                          ▒
      + 5.41% create_layouts                                                                                                                                                                                                                                                    ▒
      + 1.69% g_slist_free_full                                                                                                                                                                                                                                                 ▒
      + 0.91% cairo_image_surface_create

I have not looked into the details, but from a quick glance, it seems that a lot of time is spent figuring the text size --- here, there are merely 200 notifications. For 200 notifications, it still takes about 150ms to redraw them each second. I'm not sure where the room for improvement mostly is, but I expect that all of this is redrawn only when the text changes, that is, every second.

Either part of these computations can be cached from one redraw to the next (but the age part makes it hard, I guess), or maybe it would be a good idea to simply stop drawing when the size of the notification stack exceeds the size of the screen? (I expect this is what the notification_limit setting is about, though).

[fwsmit]

What you're saying makes sense. Dunst should only wake up once a second to update the timestamps. I would suggest every time the real time gets to the next second. This can be fixed in queues_get_next_datachange in queues.c. This is also the function for which you can write a test.

The draw code could be optimized, but I don't think it needs to, since we (should) only draw about once a second at most.

[fwsmit]

I would also say that the notification limit should help against it. Setting it to some reasonable value by default should also help

[tobast]

What you're saying makes sense. Dunst should only wake up once a second to update the timestamps. I would suggest every time the real time gets to the next second. This can be fixed in queues_get_next_datachange in queues.c. This is also the function for which you can write a test.

In practice, this is what this PR's code does: by flooring the notifications' timestamps (for display purposes), this ensures that the next wake-up for this purpose is when the real time is at an exact second. It also does not do so when there is no notification age to update. If you prefer, I could rewrite this to do explicitly what you suggest (check that there is one notification needing update, and if so, wait until the next exact second), but I find the code quite elegant this way.

I could indeed write a test in any case, though.

The draw code could be optimized, but I don't think it needs to, since we (should) only draw about once a second at most.

This problem is independent, but this is not exactly true: it does trigger only once a second, but with ~200 notifications, the (single) update takes about 150ms, which is already a 15% CPU usage for something that should not, I believe, be compute-intensive.

Setting a reasonable notification_limit value does help tremendously, though.

[fwsmit]

I'd suggest to move the flooring to inside the if statement. That's a little more explicit and makes sure you aren't too early.

gint64 next_second = time - time % S2US(1);
sleep = MIN(sleep, (S2US(1) - (next_second % S2US(1))));

[tobast]

Done in the current revision.

[fwsmit]

In practice, this is what this PR's code does: by flooring the notifications' timestamps (for display purposes), this ensures that the next wake-up for this purpose is when the real time is at an exact second. It also does not do so when there is no notification age to update. If you prefer, I could rewrite this to do explicitly what you suggest (check that there is one notification needing update, and if so, wait until the next exact second), but I find the code quite elegant this way.

I have suggested a way that's a little more explicit and hopefully easier to read.

I could indeed write a test in any case, though.

👍

This problem is independent, but this is not exactly true: it does trigger only once a second, but with ~200 notifications, the (single) update takes about 150ms, which is already a 15% CPU usage for something that should not, I believe, be compute-intensive.

Setting a reasonable notification_limit value does help tremendously, though.

Yes, could you also do that?

[tobast]

I could indeed write a test in any case, though.

+1

Done

Setting a reasonable notification_limit value does help tremendously, though.

Yes, could you also do that?

Done

It also seems to me that dunst.c:95

gint64 sleep = queues_get_next_datachange(now);

is actually wrong: computing the sleep delay from now, which is obtained a bit higher with

gint64 now = time_monotonic_now();

is problematic, because between those two lines, all the loop logic happens, some of which might be taking time. It seems reasonable to use the same value for now throughout the computations (at least to have consistent behaviour), but I believe it would be more reasonable to query time_monotonic_now() a second time for computing the sleep delay? If this seems correct to you, I can also fix this.

[tobast]

bc257cf also ensures that run() only has a single active GLib timeout. In multiple cases, while stress-testing, I noticed that multiple timers were active. This can happen if a timeout is set, run is woken up by an incoming notification, and the new computed timeout is before the old one, but it seems not to be the only case — though I don't understand how. In this case, a timeout is added, but the old remains active, and when it ticks, it adds again its own timeout (reason == 0). This goes on forever, and causes dunst to wake up multiple times when a single time is needed.

[fwsmit]

It also seems to me that dunst.c:95

gint64 sleep = queues_get_next_datachange(now);

is actually wrong: computing the sleep delay from now, which is obtained a bit higher with

gint64 now = time_monotonic_now();

is problematic, because between those two lines, all the loop logic happens, some of which might be taking time. It seems reasonable to use the same value for now throughout the computations (at least to have consistent behaviour), but I believe it would be more reasonable to query time_monotonic_now() a second time for computing the sleep delay? If this seems correct to you, I can also fix this.

I see I've changed that in #1073, more specifically in 1fc9cb6. I'll have to think a bit more about why I did that. It comes done to the question if queues_update and queues_get_next_datachange need the same time.

bc257cf also ensures that run() only has a single active GLib timeout. In multiple cases, while stress-testing, I noticed that multiple timers were active. This can happen if a timeout is set, run is woken up by an incoming notification, and the new computed timeout is before the old one, but it seems not to be the only case — though I don't understand how. In this case, a timeout is added, but the old remains active, and when it ticks, it adds again its own timeout (reason == 0). This goes on forever, and causes dunst to wake up multiple times when a single time is needed.

Perhaps this is related: #1078

[fwsmit]

I think it might be more sane to calculate the time at which the sleep should end, instead of the duration of the sleep. This way slow code doesn't impact the sleep duration (keep in mind the timer is still not guaranteed to be accurate).

[tobast]

I see I've changed that in #1073, more specifically in 1fc9cb6. I'll have to think a bit more about why I did that. It comes done to the question if queues_update and queues_get_next_datachange need the same time.

Actually, queues_get_next_datachange might need the same time as queues_update. The former seeks the event closest in time that should wake up dunst, and the latter processes events that are due at the time it is passed, so it might be possible that update is called with time t, and thus does not process some event due at t+1μs, but takes more than 1μs to do so. If the next due event is 1s later, and queues_get_next_datachange is given eg. t+10, it will request sleep for 1s, ignoring the event at t+1μs.

I think it might be more sane to calculate the time at which the sleep should end, instead of the duration of the sleep. This way slow code doesn't impact the sleep duration (keep in mind the timer is still not guaranteed to be accurate).

This would indeed avoid the issue above and looks cleaner.

I don't believe timer accuracy is needed anyway? However, as I found that with lots of notifications, queues_update can take >100ms, it feels like it becomes necessary to take this into account.

Perhaps this is related: #1078

It might be, but it doesn't look like the same issue. What I noticed was that dunst woke up about once a second (to update notifications' age), then 1-4ms later, possibly multiple times: eg. sleep duration sequence could be 1s, 2ms, 1ms, 1s, 2ms, 1ms, etc.

[tobast]

I think it might be more sane to calculate the time at which the sleep should end, instead of the duration of the sleep. This way slow code doesn't impact the sleep duration (keep in mind the timer is still not guaranteed to be accurate).

This is implemented, with tests updated, in the latest revision.

[fwsmit]

Thanks for taking the time to debug this and find a good solution. I'll merge this now

[biopsin]

This PR broke disabling idle_threshold when setting = -1 as spesified in dunstrc

[tobast]

I'll have a look into this as soon as I get time.