Incorrect timings on event from using `Instant::now` #1289

Doublonmousse · 2024-11-12T17:51:30Z

In the input file, there is this line

rnote/crates/rnote-ui/src/canvas/input.rs

Line 21 in 7f3ff8a

let now = Instant::now();

That uses the instant at which the controller is called for the pointer controller to calculate the time of the event (or more precisely, gives the timestamp for the latest event of that gdk::Event).

But this creates erroneous times. Debugging what's given by #1235, we get the following

┌─────────────┬──────────────────────────┬────────────────┬────────────┬────────────┬────────────────┐
│ speed       ┆ positions                ┆ delta position ┆ delta_time ┆ status_pen ┆ one_time_speed │
│ ---         ┆ ---                      ┆ ---            ┆ ---        ┆ ---        ┆ ---            │
│ f64         ┆ array[f64, 2]            ┆ f64            ┆ f64        ┆ str        ┆ f64            │
╞═════════════╪══════════════════════════╪════════════════╪════════════╪════════════╪════════════════╡
│ 972.168716  ┆ [227.732923, 101.225992] ┆ 6.571739       ┆ 0.009849   ┆ Proximity  ┆ 667.249416     │
│ 883.789741  ┆ [227.732923, 101.225992] ┆ 0.0            ┆ 0.0014774  ┆ Down       ┆ 0.0            │ 
│ 10000.0     ┆ [223.591976, 101.919672] ┆ 4.198647       ┆ 0.0        ┆ Down       ┆ null           | 
│ 9143.296429 ┆ [221.321795, 102.31905]  ┆ 2.305043       ┆ 0.004      ┆ Down       ┆ 576.260717     │
│ 8376.738644 ┆ [218.526114, 102.844562] ┆ 2.844643       ┆ 0.004      ┆ Down       ┆ 711.160797     │
│ 10000.0     ┆ [214.805568, 103.664364] ┆ 3.809796       ┆ 0.0001306  ┆ Down       ┆ 29171.483352   │
│ 9175.957186 ┆ [211.169086, 104.547222] ┆ 3.742116       ┆ 0.004      ┆ Down       ┆ 935.529043     │
│ 8406.43496  ┆ [208.415475, 105.261924] ┆ 2.844851       ┆ 0.004      ┆ Down       ┆ 711.212699     │
│ 7686.83764  ┆ [206.523649, 105.787437] ┆ 1.963458       ┆ 0.004      ┆ Down       ┆ 490.864439     │
│ 10000.0     ┆ [204.631849, 106.291927] ┆ 1.957912       ┆ 0.0        ┆ Down       ┆ null           │
└─────────────┴──────────────────────────┴────────────────┴────────────┴────────────┴────────────────┘

What we're concerned about is the delta position and delta time between two events (and the ratio of the two, in the last column). This is with the BacklogPolicy::NoLimit option. And we see we get events with a non zero position difference and a zero time delta (not just close to zero, EXACTLY 0).

Looking at the raw event data, the first three events are here :

RawEvent(
    x=[227.7329226372115], 
    y=[101.22599202560606], 
    event_type='other', 
    time_str=['Instant { t: 1383023.4689412s }'], 
    gtk_time=[1382966381]
    )
RawEvent(
    x=[227.7329226372115], 
    y=[101.22599202560606], 
    event_type='ButtonPress',  // the button Press Event
    time_str=['Instant { t: 1383023.4704186s }'], 
    gtk_time=[1382966381] // for gtk, this is sent at exactly the same position as the previous location with the SAME time
    )
RawEvent(
    x=[223.59197575860676, 221.3217951414422, 218.5261142707021], 
    y=[101.91967188204403, 102.31904963454664, 102.84456208919609], 
    event_type='other', 
    time_str=['Instant { t: 1383023.4703054s }', 'Instant { t: 1383023.4743054s }', 'Instant { t: 1383023.4783054s }'], 
    // for rnote, the first event is at 1383023.4703054s which is EARLIER than the previous event
    // at  1383023.4704186s
    gtk_time=[1382966388, 1382966392, 1382966396] // the first event is 7 ms after the last one
    )

So we get later events placed before previous events, when there is a non-empty history. This is why we get exactly 0.0 as the difference of instants ((time - last_element_time).as_secs_f64() saturates to 0 if the difference is negative).

So we should add somewhere (in the canvas/ui code ?) a mapping between Instant and gtk's u32 time stamping (maybe set this on the first event with a time stamp. so we have a Instant::now corresponding to a u32 value and do other calculations relative to this to still keep std::Instant lower in the engine code).
I don't know whether there is other precaution to take regarding gtk4's time (does it overflow ? I mean it'll take a while for that to happen, 50 days from my napkin math, but if it increases with the system clock and not screen time, it's possible to have this issue on tablets that are never shut down with rnote staying open)

This is an issue because we rely on correct timings for the ink stroke modeler and the upcoming eraser PR (increase size with speed).

There's a little bit of observer effect (timing changes from logging this), though I had the same issue without logging (infinite speed upon touching the screen). I guess this issue only really manifest if the gtk event history is not empty, so only for pen that refresh more quickly than the display.

Without the BacklogPolicy changed, and logging only the eraser data, I get a delta time between the ButtonPress and the next event in the 6e-5 s.

The text was updated successfully, but these errors were encountered:

Doublonmousse self-assigned this Nov 12, 2024

Doublonmousse added bug Something isn't working input input related issues labels Nov 12, 2024

Doublonmousse linked a pull request Nov 12, 2024 that will close this issue

mapping between gtk timestamp and instant #1290

Draft

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Incorrect timings on event from using `Instant::now` #1289

Incorrect timings on event from using `Instant::now` #1289

Doublonmousse commented Nov 12, 2024 •

edited

Loading

Incorrect timings on event from using Instant::now #1289

Incorrect timings on event from using Instant::now #1289

Comments

Doublonmousse commented Nov 12, 2024 • edited Loading

Incorrect timings on event from using `Instant::now` #1289

Incorrect timings on event from using `Instant::now` #1289

Doublonmousse commented Nov 12, 2024 •

edited

Loading