Live render partially working #198

Valentin271 · 2023-12-15T10:56:44Z

Description

Sometimes when saving a file, the live reload will not render the whole file (screen 3) or just a blank screen (screen 2).
The initial render - when starting the app - is always ok (screen 1).

Triggering the reload again will end up in one of the 3 mentioned cases.
I noticed saving with modifications will more often lead to a correct render than saving without.

It seems that the larger the file the easier it is to reproduce. While testing, I started to encounter the issue with ~250 lines, but it was very rare.

I'd like to help more but couldn't find any log of why that happens, neither stdout/stderr or files.

From an outside point of view it seems to me like there is some non-determinism going on which causes inlyne to sort of exit early.

Additional details

Screenshots

Screen 1, working correctly on open

Screen 2, blank render on live reload

Screen 3, partially rendered after live reload (notice the size of the scrollbar compared to screen 1)

I run ubuntu with i3wm and neovim v0.9.4 (if that's any relevant).

$ uname -a
Linux xubuntu 5.15.0-91-generic #101-Ubuntu SMP Tue Nov 14 13:30:08 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

$ inlyne --version
inlyne 0.3.3

Also happens on main, 0.3.2

I mainly tested against the ratatui breaking change file and the other md files in the repo.

Please tell me if I can be of any more help!

EDIT: on version 0.2.1, I don't have any blank screen, sometimes a partial render (but very rare). Hope that helps.

CosmicHorrorDev · 2023-12-15T17:08:56Z

I'd like to help more but couldn't find any log of why that happens, neither stdout/stderr or files.

You can pass INLYNE_LOG with a log filter to inlyne. Something like

$ INLYNE_LOG="warn,inlyne=trace" inlyne ratatui/BREAKING_CHANGES.md

It's pretty hit or miss on what actually has logs, but the file watcher is pretty log-happy since it's notoriously annoying to work with

I'll see if I can reproduce later today

Valentin271 · 2023-12-15T17:19:29Z

You can pass the INLYNE_LOG with a log filter to inlyne

Thanks, I'll be sure to upload the logs and investigate on it.

At a quick glance I don't see anything standing out except multiple file events for a single write.

CosmicHorrorDev · 2023-12-15T17:25:34Z

Thanks, I'll be sure to upload the logs and investigate on it.

Thanks! I appreciate all the help investigating

At a quick glance I don't see anything standing out except multiple file events for a single write.

That's expected for neovim. More context here #104

Valentin271 · 2023-12-15T18:31:11Z

I feel your pain :/

Other editors

So I tested other editors with inlyne 0.3.3:

nvim: frequently bugs out
vim, mousepad: less than ten times over hundreds of saves
echo test > file: works flawlessly even with cpu stress

In fact to reproduce with mousepad or vim I had to stress my all my CPUs by running a cargo compilation.

But um ... with neovim stressing the CPUs affected it positively ... it rendered correctly more often.

Sets of logs for each editor

nvim: Modify, Modify, Modify, Access, Modify
vim: Modify, Modify, Remove
mousepad: Access, Modify, Remove
echo >: Modify, Access

Notice vim and mousepad both re-register the file watcher, while neovim and shell redirect don't.

nvim

[2023-12-15T17:50:23Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Data(
                Any,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:50:23Z DEBUG inlyne::watcher] Reloading file
[2023-12-15T17:50:23Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Data(
                Any,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:50:23Z DEBUG inlyne::watcher] Reloading file
[2023-12-15T17:50:23Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Data(
                Any,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:50:23Z DEBUG inlyne::watcher] Reloading file
[2023-12-15T17:50:23Z TRACE inlyne::watcher] File event: Event {
        kind: Access(
            Close(
                Write,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:50:23Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Metadata(
                Any,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:50:23Z DEBUG inlyne::watcher] Reloading file

vim

[2023-12-15T17:48:53Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Name(
                From,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:48:53Z DEBUG inlyne::watcher] File may have been renamed/removed. Falling back to polling
[2023-12-15T17:48:53Z DEBUG inlyne::watcher] Successfully re-registered file watcher
[2023-12-15T17:48:53Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Metadata(
                Any,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:48:53Z DEBUG inlyne::watcher] Reloading file
[2023-12-15T17:48:53Z TRACE inlyne::watcher] File event: Event {
        kind: Remove(
            File,
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:48:53Z DEBUG inlyne::watcher] File may have been renamed/removed. Falling back to polling
[2023-12-15T17:48:53Z DEBUG inlyne::watcher] Successfully re-registered file watcher

mousepad

[2023-12-15T17:35:23Z TRACE inlyne::watcher] File event: Event {
        kind: Access(
            Close(
                Write,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:35:23Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Metadata(
                Any,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:35:23Z DEBUG inlyne::watcher] Reloading file
[2023-12-15T17:35:23Z TRACE inlyne::watcher] File event: Event {
        kind: Remove(
            File,
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T17:35:23Z DEBUG inlyne::watcher] File may have been renamed/removed. Falling back to polling
[2023-12-15T17:35:23Z DEBUG inlyne::watcher] Successfully re-registered file watcher

echo >

[2023-12-15T18:27:04Z TRACE inlyne::watcher] File event: Event {
        kind: Modify(
            Data(
                Any,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }
[2023-12-15T18:27:04Z DEBUG inlyne::watcher] Reloading file
[2023-12-15T18:27:04Z TRACE inlyne::watcher] File event: Event {
        kind: Access(
            Close(
                Write,
            ),
        ),
        paths: [
            "/home/user/code/ratatui/ratatui/BREAKING-CHANGES.md",
        ],
        attr:tracker: None,
        attr:flag: None,
        attr:info: None,
        attr:source: None,
    }

Additional info

My nvim has no swapfile/backup file whereas my vim has

Also edited the original post to add nvim version 0.9.4

CosmicHorrorDev · 2023-12-15T18:40:39Z

Thanks for all the info! I'll dig in later tonight

My hunch is that there's something funky going on with the logic for freezing the screen while the interpreter is rendering a new document. Regardless it's probably a good time to sprinkle more trace logs around

CosmicHorrorDev · 2023-12-16T00:47:13Z

Off work now, and thanks for all the info. I think it should actually be a pretty easy fix. The piece that put it all together was

My nvim has no swapfile/backup file whereas my vim has

because I wasn't able to reproduce the issue, but I was using a swapfile. After disabling that and adding some extra logging it looks like we're reading the file before it has time to fully be written to disk. Here are the logs from just continuously saving the same file where it logs the length of the file it recieved

[2023-12-16T00:41:18Z WARN  inlyne::interpreter] Recieved text with len: 117474
[2023-12-16T00:41:21Z WARN  inlyne::interpreter] Recieved text with len: 73728
[2023-12-16T00:41:23Z WARN  inlyne::interpreter] Recieved text with len: 49152
[2023-12-16T00:41:23Z WARN  inlyne::interpreter] Recieved text with len: 57344
[2023-12-16T00:41:25Z WARN  inlyne::interpreter] Recieved text with len: 24576
[2023-12-16T00:41:26Z WARN  inlyne::interpreter] Recieved text with len: 117474
[2023-12-16T00:41:27Z WARN  inlyne::interpreter] Recieved text with len: 65536
[2023-12-16T00:41:28Z WARN  inlyne::interpreter] Recieved text with len: 49152
[2023-12-16T00:41:29Z WARN  inlyne::interpreter] Recieved text with len: 73728
[2023-12-16T00:41:30Z WARN  inlyne::interpreter] Recieved text with len: 32768

CosmicHorrorDev · 2023-12-16T01:32:33Z

@Valentin271 You did all the hard work debugging everything. Do you also want to take a stab at fixing it? I don't want to steal your glory

Valentin271 · 2023-12-16T08:42:23Z

Oh so that's interesting. I guess with a swap file saving is as simple as moving/copying it, whereas without you need to write the whole file (which is probably buffered) which explains why it happens more often on bigger files.

And that's why neovim had multiple Modify upfront, saving an empty file raises only Modify, Access, Modify, and saving a file with at least one character will raise Modify, Modify, Access, Modify.

This is also why the bug started appearing more consistently around 250 lines, ~300 is where it starts to have 3 Modify (this is not consistent for some reason). Coincidentally, on the file I was testing, this represents around 8192 bytes which looks like a terribly suspicious number (maybe the size of the buffed writes?).

It all makes sense now.

EDIT: As such, bigger and bigger files will raise more and more Modify

You did all the hard work debugging everything. Do you also want to take a stab at fixing it? I don't want to steal your glory

haha thanks! You found the bug in the end.

Gladly, I'll take a look later today and try to submit a fix if I can figure it out along with the codebase.

CosmicHorrorDev · 2023-12-16T16:41:49Z

Gladly, I'll take a look later today and try to submit a fix if I can figure it out along with the codebase.

Great! Don't be afraid to reach out if you have questions. A high level overview of the relevant parts:

The interpreter - responsible for converting markdown text to the elements we care about
- The interpret_md function continuously receives markdown text
The file watcher - responsible for sending file events to the event loop
The event loop - runs the whole thing including sending any markdown text updates to the interpreter

So, the thing that needs fixing is how we read the files to send them to the interpreter. I don't really care that much about the performance of reading the markdown files specifically since it'd be incredibly rare for them to be above 1 MiB even. Maybe checking the length after finishing a read to see if they match, or reading twice, or something

Valentin271 · 2023-12-17T13:16:13Z

Thank you this was definitely helpful!

Ok so I have two sort of solution I wanted to discuss.

First solution

Just wait a few milliseconds before reloading files. On my machine 1ms is enough up to ~100kb files, after that bug reappears.
The problem is this is very hardware dependent. It could be a configurable option with 10ms as a sane default imo.

Second solution

Use notify_debouncer_mini to debounce the events. I think this is a very good solution but:

it introduces another dependency
kind of changes the implementation of the file watcher (not necessarily a big deal but I'm afraid of breaking many things)
You don't get the kind of event anymore

Its up to you to evaluate those drawbacks, let me know if you want a PR with that to evaluate and test it. I think this is the most robust solution of the twos. It would make sense for a file watcher to include a configurable debounce timing.

For a 160k file, the second solution also reduces the number of call to interpret_md to 2 instead of 22. Granted a 160k file should almost never be.

CosmicHorrorDev · 2023-12-17T17:20:30Z

You don't get the kind of event anymore

This may be a dealbreaker with the second solution for inlyne. We currently respond differently depending on the kind of events we receive since notify provides a Watch the same file regardless of its path api and we have to adapt it to get Watch the same path regardless of its file behavior instead (basically the logic enforced by this test)

Some iteration of the first solution should probably be good enough. I think going with a shorter delay while doing multiple checks should help to reduce latency. Also ideally we get a robust enough solution that we don't have to expose any additional configuration options

Valentin271 · 2023-12-17T17:27:54Z

This may be a dealbreaker with the second solution for inlyne

I just thought that the notify doc also listed this lib https://docs.rs/notify-debouncer-full/latest/notify_debouncer_full/index.html which actually transmit original notify event.
It also does things that you might be interested in.

Alright then I'll send a PR with the first solution and try to improve it.

CosmicHorrorDev · 2023-12-17T17:30:19Z

That list of features does look like it addresses all of my issues :D

Valentin271 · 2023-12-17T17:31:33Z

Yeah I thought so 😄 , shall I try to use it?

CosmicHorrorDev · 2023-12-17T17:33:51Z

Go for it!

CosmicHorrorDev added the C-bug Category: Something isn't working label Dec 15, 2023

Valentin271 mentioned this issue Dec 20, 2023

fix: filter file watcher duplicate events #200

Merged

CosmicHorrorDev closed this as completed in #200 Dec 21, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Live render partially working #198

Live render partially working #198

Valentin271 commented Dec 15, 2023 •

edited

CosmicHorrorDev commented Dec 15, 2023 •

edited

Valentin271 commented Dec 15, 2023 •

edited

CosmicHorrorDev commented Dec 15, 2023

Valentin271 commented Dec 15, 2023 •

edited

CosmicHorrorDev commented Dec 15, 2023

CosmicHorrorDev commented Dec 16, 2023

CosmicHorrorDev commented Dec 16, 2023

Valentin271 commented Dec 16, 2023 •

edited

CosmicHorrorDev commented Dec 16, 2023 •

edited

Valentin271 commented Dec 17, 2023

CosmicHorrorDev commented Dec 17, 2023

Valentin271 commented Dec 17, 2023

CosmicHorrorDev commented Dec 17, 2023

Valentin271 commented Dec 17, 2023

CosmicHorrorDev commented Dec 17, 2023

Live render partially working #198

Live render partially working #198

Comments

Valentin271 commented Dec 15, 2023 • edited

Description

Additional details

CosmicHorrorDev commented Dec 15, 2023 • edited

Valentin271 commented Dec 15, 2023 • edited

CosmicHorrorDev commented Dec 15, 2023

Valentin271 commented Dec 15, 2023 • edited

Other editors

Sets of logs for each editor

Additional info

CosmicHorrorDev commented Dec 15, 2023

CosmicHorrorDev commented Dec 16, 2023

CosmicHorrorDev commented Dec 16, 2023

Valentin271 commented Dec 16, 2023 • edited

CosmicHorrorDev commented Dec 16, 2023 • edited

Valentin271 commented Dec 17, 2023

First solution

Second solution

CosmicHorrorDev commented Dec 17, 2023

Valentin271 commented Dec 17, 2023

CosmicHorrorDev commented Dec 17, 2023

Valentin271 commented Dec 17, 2023

CosmicHorrorDev commented Dec 17, 2023

Valentin271 commented Dec 15, 2023 •

edited

CosmicHorrorDev commented Dec 15, 2023 •

edited

Valentin271 commented Dec 15, 2023 •

edited

Valentin271 commented Dec 15, 2023 •

edited

Valentin271 commented Dec 16, 2023 •

edited

CosmicHorrorDev commented Dec 16, 2023 •

edited