Output filtered text to Kakoune incrementally

[malte-v]

I'd like to use Kakoune as a pager, but when I do git log in a repository with a long history, the processing of the ANSI sequences takes ages and I have to wait quite a long time until I see any text. Can we let the filtering program output the filtered text right away and then add highlighting later? That would make it viable to actually use Kakoune as a pager for large portions of text.

[eraserhd]

Possibly. It might be better to figure out what is taking Kakoune so long. If you have a particularly slow file, post that and your processing time and we can see what's going on.

[eraserhd]

Piping a screen capture to kakoune, for me, gets me these timings:

shell:  buffer_basename="${kak_buffile##*/}"
shell execution took 26884 us (spawn: 8019, wait: 18838)
count: 1, total: 26884 (0.03s)

shell: tmp="$kak_client_env_KITTY_PIPE_DATA"
shell execution took 8021 us (spawn: 2539, wait: 5469)
count: 1, total: 8021 (0.008s) 

shell:  eval set -- "$kak_quoted_opt_extra_word_chars"
shell execution took 8446 us (spawn: 2315, wait: 6116)
count: 1, total. 8446 (0.008s)

shell: tmp="$kak_selection_desc"
shell execution took 8060 us (spawn: 2190, wait: 5859)
shell execution took 7429 us (spawn: 1998, wait: 5420)
shell execution took 7731 us (spawn: 2173, wait: 5547)
shell execution took 7661 us (spawn: 2117, wait: 5533)
shell execution took 7892 us (spawn: 2166, wait: 5715)
shell execution took 7146 us (spawn: 2027, wait: 5109)
shell execution took 7916 us (spawn: 2107, wait: 5799)
shell execution took 7685 us (spawn: 2228, wait: 5447)
shell execution took 7475 us (spawn: 2032, wait: 5433)
shell execution took 7493 us (spawn: 2102, wait: 5380)
count: 10, total: 76488 (0.08s)

shell:  printf "select %s\n" "$kak_hook_param"
shell execution took 7022 us (spawn: 1841, wait: 5174)
shell execution took 6774 us (spawn: 1769, wait: 4997)
shell execution took 6336 us (spawn: 1583, wait: 4746)
shell execution took 6423 us (spawn: 1620, wait: 4795)
shell execution took 6779 us (spawn: 1688, wait: 5084)
shell execution took 6629 us (spawn: 1774, wait: 4849)
shell execution took 7039 us (spawn: 1666, wait: 5365)
shell execution took 6824 us (spawn: 1749, wait: 5068)
shell execution took 6579 us (spawn: 1575, wait: 4997)
shell execution took 6661 us (spawn: 1633, wait: 5017)
count: 10, total: 67066 (0.07s)

shell: mktemp
shell execution took 13689 us (spawn: 1750, wait: 11936)
shell execution took 11604 us (spawn: 1593, wait: 10008)
shell execution took 10838 us (spawn: 1370, wait: 9465)
shell execution took 11708 us (spawn: 1451, wait: 10253)
shell execution took 11712 us (spawn: 1508, wait: 10201)
shell execution took 11678 us (spawn: 1559, wait: 10116)
shell execution took 12055 us (spawn: 1720, wait: 10332)
shell execution took 11607 us (spawn: 1520, wait: 10085)
shell execution took 11655 us (spawn: 1409, wait: 10243)
shell execution took 11736 us (spawn: 1499, wait: 10234)
count: 10, total: 118282 (0.12s)

That's about 1.8s, which is about what it feels like (which I agree is bad).

EDIT: Fixed my math, and we're at <200ms, so none of this sesems to explain the lag.

[malte-v]

I used Kakoune to view the history of my nixpkgs checkout:

PAGER='kak -e ansi-enable' git log

After about six and a half minutes, the beautifully colored output (~2 million lines) appeared on screen. When not running ansi-enable at startup, the buffer gets littered with ANSI sequences, but the most recent log entries appear instantly and it takes around three seconds for Kakoune to add all 2 million lines to the buffer (during this time it says [fifo] in the status line).

[eraserhd]

If you do this:

PAGER='dd of=/tmp/foo.txt' git log

Edit /tmp/foo.txt, how long does ansi-render take?

[malte-v]

It took a little over 11 minutes.

[eraserhd]

If you do time kak-ansi-filter </tmp/foo.txt >/tmp/bar.txt 2>bar.kak?

Finally, if you kak /tmp/bar.txt, how long to source /tmp/bar.kak.

(Also, what OS are you on?)

I'm quite certain that the filter will be very quick, and editing the file itself should be very quick, and the logs say that sourcing the highlighting is very quick. I'll bet this means that there's some kind of cache of highlighting data that is difficult to compute and is slow.

[malte-v]

$ time kak-ansi-filter </tmp/foo.txt >/tmp/bar.txt 2>/tmp/bar.kak
kak-ansi-filter <  >  5.59s user 10.57s system 99% cpu 16.258 total

Sourcing /tmp/bar.kak with /tmp/bar.txt opened is instant (not sure about that; Kakoune just stays responsive), but no highlighting is added and nothing is appended to the *debug* buffer. I'm on NixOS (recent nixpkgs rev) with kak-ansi d72fb3dc14598e4a4719d9fcf68cad5a73ebbf1a.

[eraserhd]

Oh... I think I know what it might be!

If you kak /tmp/foo.txt, then do |cat /tmp/bar.txt with the above files, how long before it becomes responsive?

It might be Kakoune's change-diffing algorithm, which is O(ND) complexity, and N is large here and D also seems like it is large. (How many words are in /tmp/bar.kak, and how many bytes in each of those files?)

[malte-v]

|cat /tmp/bar.txt with /tmp/foo.txt opened takes around 2.5 seconds (not doing anything with the ANSI sequences).

$ wc /tmp/foo.txt /tmp/bar.txt /tmp/bar.kak
  2151694   6902945  70010549 /tmp/foo.txt
  2151694   6902945  67823185 /tmp/bar.txt
        1    273402   7370957 /tmp/bar.kak
  4303389  14079292 145204691 total

[eraserhd]

I'm at a loss, and while I know there's speed issues, I'm not seeing the same thing as you here AFAICT.

Can you make a profile build and post the results? Off the top of my head, it will be something like:

• Checkout out kakoune source.
• cd kakoune
• nix-shell '<nixpkgs>' -A kakoune-unwrapped (for build environment)
• make -C src CXXFLAGS+=-pg debug
• `PAGER='./src/kak.debug -n -e "source /nix/store/wherever/kak-ansi/rc/ansi.kak ; ansi-enable"' git -C /wherever/you/log log
• gprof ./src/kak.debug /wherever/you/log/gmon.out >/tmp/report.txt

[malte-v]

Weird. When using the debug version I just built, I get this error in the *debug* buffer (and no highlighting):

error running hook BufReadFifo(1.1,1020.53)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(1020.53,2059.26)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(2059.26,3114.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(3114.1,3849.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(3849.1,3940.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(3940.1,4053.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(4053.1,4098.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(4098.1,4140.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(4140.1,4194.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(4194.1,4230.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(4230.1,4284.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(4284.1,4320.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
error running hook BufReadFifo(4320.1,4365.1)/ansi: 2:9: 'evaluate-commands' no such command: '{'
...

~Perhaps the error was somehow supressed by the stuff in my kakrc?~ It also happens with my normal Kakoune setup now. :/ mawww/kakoune@bdee3abd88ebc88ef39d47c6c8c63694d90bd3f2 kak-ansi d72fb3dc14598e4a4719d9fcf68cad5a73ebbf1a

[eraserhd]

With the -n, it shouldn't source your config.

I'm not sure, but maybe you have a ~/.config/kak/autoload directory that's preventing loading other things? Remove it if so.

[eraserhd]

wait... It seems like percent signs got deleted in ansi.kak?

[eraserhd]

I pushed a fix for a bracket.

[malte-v]

I pushed a fix for a bracket.

Thanks, it works now.

https://gist.github.com/574e9fcc55808a9f768ed36201493be5

[eraserhd]

kakoune has merged significant performance fixes for this case, and I've pushed significant additional performance improvements for kak-ansi, so I'm going to consider this closed.