Vim surprisingly slow?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
28 messages Options
12
Reply | Threaded
Open this post in threaded view
|

Vim surprisingly slow?

Tim Chase
Taking on the challenge listed here

https://dev.to/jorinvo/csv-challenge-1al

it provides a .json file link to mung into date-named files (never
mind that these happen to all be the same date), I came up with this
vim solution:

:g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
'\1\2\3','').'.txt'|s//\1,\2/|exec ".w!>>".s

which works.  But for some reason, it is *painfully* slow on my
machine.  The basic intent is that it identifies rows with a (fake)
credit-card number, snapshots the YYYYMMMDD.txt filename, then turns
the row into a CSV entry ("name, CC"), and writes (appending) that one
line into the output filename.

The whole thing should happen in a blink. Maybe a second at worst.
But this was walk-away-do-something-and-come-back slow.

If I change the "exec" to an "echo", it's as fast as I expect.

Any idea what might be making the exec so slow?

-tim




--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Christian Brabandt

On So, 12 Nov 2017, Tim Chase wrote:

> Taking on the challenge listed here
>
> https://dev.to/jorinvo/csv-challenge-1al
>
> it provides a .json file link to mung into date-named files (never
> mind that these happen to all be the same date), I came up with this
> vim solution:
>
> :g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
> s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
> '\1\2\3','').'.txt'|s//\1,\2/|exec ".w!>>".s
>
> which works.  But for some reason, it is *painfully* slow on my
> machine.  The basic intent is that it identifies rows with a (fake)
> credit-card number, snapshots the YYYYMMMDD.txt filename, then turns
> the row into a CSV entry ("name, CC"), and writes (appending) that one
> line into the output filename.
>
> The whole thing should happen in a blink. Maybe a second at worst.
> But this was walk-away-do-something-and-come-back slow.
>
> If I change the "exec" to an "echo", it's as fast as I expect.
>
> Any idea what might be making the exec so slow?

No idea and I bet running it under gdb will make it even slower :(

Nevertheless can you try this with a debug Vim and hit <Ctrl>-C

This should give us a clue, which codepath is slow. Please try this
several times, so we are sure, that we hit the slow codepath.

Of course, easier would be to provide a correct profiling information :)

Christian
--
Es gibt erfülltes Leben, trotz vieler unerfüllter Wünsche.
                -- Dietrich Bonhoeffer

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Erik Falor
On Mon, Nov 13, 2017 at 09:33:49PM +0100, Christian Brabandt wrote:

>
> On So, 12 Nov 2017, Tim Chase wrote:
>
> > Taking on the challenge listed here
> >
> > https://dev.to/jorinvo/csv-challenge-1al
> >
> > it provides a .json file link to mung into date-named files (never
> > mind that these happen to all be the same date), I came up with this
> > vim solution:
> >
> > :g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
> > s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
> > '\1\2\3','').'.txt'|s//\1,\2/|exec ".w!>>".s
> >
> > which works.  But for some reason, it is *painfully* slow on my
> > machine.  The basic intent is that it identifies rows with a (fake)
> > credit-card number, snapshots the YYYYMMMDD.txt filename, then turns
> > the row into a CSV entry ("name, CC"), and writes (appending) that one
> > line into the output filename.
> >
> > The whole thing should happen in a blink. Maybe a second at worst.
> > But this was walk-away-do-something-and-come-back slow.
> >
> > If I change the "exec" to an "echo", it's as fast as I expect.
> >
> > Any idea what might be making the exec so slow?
>
> No idea and I bet running it under gdb will make it even slower :(
>
> Nevertheless can you try this with a debug Vim and hit <Ctrl>-C
>
> This should give us a clue, which codepath is slow. Please try this
> several times, so we are sure, that we hit the slow codepath.
>
> Of course, easier would be to provide a correct profiling information :)
I profiled Vim while running this command, but my gprof-fu isn't strong enough
to see the problem. I tried different combinations of old/new regexp engine,
enabling/disabling autocmds, :silent, but these didn't make a discernible
difference.

The gprof logs can be found at http://unnovative.net/json_challenge/,
if anybody smarter than I cares to take a look.

The odd thing that I noticed is that, according to htop, the Vim process spends
lots of cycles in IOWait.

Here's what iotop shows during a typical run:

Total DISK READ :       0.00 B/s | Total DISK WRITE :    1372.27 K/s
Actual DISK READ:       0.00 B/s | Actual DISK WRITE:       2.68 M/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
  304 be/3 root        0.00 B/s    0.00 B/s  0.00 % 80.22 % [jbd2/nvme0n1p2-]
17734 be/4 fadein      0.00 B/s 1372.27 K/s  0.00 %  0.89 % vim -c source slow.vim data.json


That's a lot of writing to my hard disk nvme0n1p2. It looks like Vim thrashing
a temp file somewhere, but I didn't see anything that looked likely under
/proc/$(pgrep vim)/fd, and

         lsof -p $(pgrep vim)

didn't turn up anything that looked out of the ordinary. Just to be sure I also
tried disabling the swap file

        :set noswf

but still, Vim thrashes.

--
Erik Falor
Registered Linux User #445632                    http://unnovative.net

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.

signature.asc (169 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Nazri Ramliy
In reply to this post by Tim Chase
On Sun, Nov 12, 2017 at 10:21 PM, Tim Chase <[hidden email]> wrote:
> If I change the "exec" to an "echo", it's as fast as I expect.
>
> Any idea what might be making the exec so slow?

It's vim writing to disk that makes it slow. I ran it on SSD it's
fast, on a spindle disk it's slow. I use fatrace[1] to see the file
create/write/close operations done by vim. So vim is writing to the
file for each line that matches the pattern.

$ sudo fatrace
...
vim(4719): WO /home/nazri/disk/20150425.txt
vim(4719): W /home/nazri/disk/20150425.txt
vim(4719): CW /home/nazri/disk/20150425.txt
vim(4719): CW /home/nazri/disk/20150425.txt
vim(4719): CO /home/nazri/disk
vim(4719): WO /home/nazri/disk/20150425.txt
vim(4719): W /home/nazri/disk/20150425.txt
vim(4719): CW /home/nazri/disk/20150425.txt
vim(4719): CW /home/nazri/disk/20150425.tx
...

nazri

[1] https://launchpad.net/fatrace https://github.com/truncs/fatrace

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Tim Chase
On 2017-11-14 18:57, Nazri Ramliy wrote:

> On Sun, Nov 12, 2017 at 10:21 PM, Tim Chase <[hidden email]>
> wrote:
> > If I change the "exec" to an "echo", it's as fast as I expect.
> >
> > Any idea what might be making the exec so slow?  
>
> It's vim writing to disk that makes it slow. I ran it on SSD it's
> fast, on a spindle disk it's slow. I use fatrace[1] to see the file
> create/write/close operations done by vim. So vim is writing to the
> file for each line that matches the pattern.

Yes, this was on a spinning-rust disk rather than a SSD/NVME drive.
And yes, based on the command, it should be doing an open/write/close
for each line.  However, I'm nigh certain I've done things like this
in the past (whether within vim or things like Bash/Python scripts)
and it's not nearly as painful.  Besides, the OS (Debian in this case)
should be fairly aggressive in caching the recently-used filesystem
metadata, so I'd expect the first open/close to have some reasonable
overhead, but subsequent ones should be coming out of cache, not
directly read off the drive.

Thanks Nazri, Erik, and Christian for investigative work. :-)

-tim


--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Keith Christian-2
On Linux, /tmp is usually a RAMDISK, try that for a speed improvement.

Keith 

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Christian Brabandt
In reply to this post by Nazri Ramliy

On Di, 14 Nov 2017, Nazri Ramliy wrote:

> On Sun, Nov 12, 2017 at 10:21 PM, Tim Chase <[hidden email]> wrote:
> > If I change the "exec" to an "echo", it's as fast as I expect.
> >
> > Any idea what might be making the exec so slow?
>
> It's vim writing to disk that makes it slow. I ran it on SSD it's
> fast, on a spindle disk it's slow. I use fatrace[1] to see the file
> create/write/close operations done by vim. So vim is writing to the
> file for each line that matches the pattern.

So how slow is it, if we skip the `.w >> output` part of the command,
but rather gather the matches in a list?

Christian
--
"Wes Brot ich esse, des Lied ich singe" ist ein Soldatenlied, das
Ludwig XIV. mit Louvois und seinem Beichtvater Tellier gedichtet und
in Musik gesetzt hat.
                -- Klinger, Betrachtungen und Gedanken

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Tim Chase
On 2017-11-14 18:17, Christian Brabandt wrote:

> On Di, 14 Nov 2017, Nazri Ramliy wrote:
>
> > On Sun, Nov 12, 2017 at 10:21 PM, Tim Chase
> > <[hidden email]> wrote:  
> > > If I change the "exec" to an "echo", it's as fast as I expect.
> > >
> > > Any idea what might be making the exec so slow?  
> >
> > It's vim writing to disk that makes it slow. I ran it on SSD it's
> > fast, on a spindle disk it's slow. I use fatrace[1] to see the
> > file create/write/close operations done by vim. So vim is writing
> > to the file for each line that matches the pattern.  
>
> So how slow is it, if we skip the `.w >> output` part of the
> command, but rather gather the matches in a list?

Using this as my test:

:let a=[] | g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
'\1\2\3','').'.txt'|s//\1,\2/|exec "call
add(a,\"".s.getline('.')."\")"

The above makes the following changes:

- initializes "a" to be an empty array

- changes the ".w! >>".s after the exec to a "call add(a,"...")"
  accessing both the filename and the text-line in question

Comparing timings, it's inappreciably different from the "echo"
version, so no major speed issues there.  It seems to be the ".w!>>"
that is the bottleneck.

Thanks again!

-tim




--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Tim Chase
In reply to this post by Erik Falor
On 2017-11-14 00:08, Erik Falor wrote:
> Here's what iotop shows during a typical run:
>
> Total DISK READ :       0.00 B/s | Total DISK WRITE :    1372.27 K/s
> Actual DISK READ:       0.00 B/s | Actual DISK WRITE:       2.68 M/s
>   TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>
> COMMAND 304 be/3 root        0.00 B/s    0.00 B/s  0.00 % 80.22 %
> [jbd2/nvme0n1p2-] 17734 be/4 fadein      0.00 B/s 1372.27 K/s  0.00
> %  0.89 % vim -c source slow.vim data.json

I see similar behavior on mine, with iotop reporting 80-90% of the
usage on the home partition of my drive (where I was writing the file
in question).

I started poking around in the vim source, but nothing stands out to
me other than possibly attempting to run autocmds for every ".w!>>"
which might have some sort of amplification factor.

I don't have a good way to see if it's actually (re)reading the
output file (and possibly executing autocmds on it or other vast
labor) every time it appends to it.

The difference between the "exec '.w>>'" case and the other tests is
striking.  The other tests complete in under a second.  Meanwhile,
the version attempting to append the line to the file is taking
*minutes* to write/append ~5000 lines.

-tim



--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Christian Brabandt

On Di, 14 Nov 2017, Tim Chase wrote:

> On 2017-11-14 00:08, Erik Falor wrote:
> > Here's what iotop shows during a typical run:
> >
> > Total DISK READ :       0.00 B/s | Total DISK WRITE :    1372.27 K/s
> > Actual DISK READ:       0.00 B/s | Actual DISK WRITE:       2.68 M/s
> >   TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>
> > COMMAND 304 be/3 root        0.00 B/s    0.00 B/s  0.00 % 80.22 %
> > [jbd2/nvme0n1p2-] 17734 be/4 fadein      0.00 B/s 1372.27 K/s  0.00
> > %  0.89 % vim -c source slow.vim data.json
>
> I see similar behavior on mine, with iotop reporting 80-90% of the
> usage on the home partition of my drive (where I was writing the file
> in question).
>
> I started poking around in the vim source, but nothing stands out to
> me other than possibly attempting to run autocmds for every ".w!>>"
> which might have some sort of amplification factor.
>
> I don't have a good way to see if it's actually (re)reading the
> output file (and possibly executing autocmds on it or other vast
> labor) every time it appends to it.
>
> The difference between the "exec '.w>>'" case and the other tests is
> striking.  The other tests complete in under a second.  Meanwhile,
> the version attempting to append the line to the file is taking
> *minutes* to write/append ~5000 lines.

Some more things to try:
Does `:set ei=all` or using `:noa :.w` make a difference perhaps?
Also does it work better if you explicitly use e.g. writefile('', 'a')?

Christian
--
Warum haben einige Trabbis eine heizbare Heckscheibe?
Damit man beim Schieben warme Hände hat.

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Tim Chase
On 2017-11-14 22:15, Christian Brabandt wrote:
> Some more things to try:
> Does `:set ei=all` or using `:noa :.w` make a difference perhaps?

Makes no difference that I could tell.  I ^C'ed it after about 30
seconds in both cases.

> Also does it work better if you explicitly use e.g. writefile('',
> 'a')?

Much faster!

:g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
s=substitute(getline('.'),
'.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*','\1\2\3','').'.txt'|s//\1,\2/|call
writefile([getline('.')], s, 'a')


runs in about the same time as the "echo" version or the "append it
to a list" version (i.e., one second or less).

-tim



--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Christian Brabandt

On Di, 14 Nov 2017, Tim Chase wrote:

> On 2017-11-14 22:15, Christian Brabandt wrote:
> > Some more things to try:
> > Does `:set ei=all` or using `:noa :.w` make a difference perhaps?
>
> Makes no difference that I could tell.  I ^C'ed it after about 30
> seconds in both cases.

Okay, no autocommand comes in the way.

> > Also does it work better if you explicitly use e.g. writefile('',
> > 'a')?
>
> Much faster!
>
> :g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
> s=substitute(getline('.'),
> '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*','\1\2\3','').'.txt'|s//\1,\2/|call
> writefile([getline('.')], s, 'a')
>
>
> runs in about the same time as the "echo" version or the "append it
> to a list" version (i.e., one second or less).

I am puzzled now. Is that buffer loaded? Perhaps Vim (re-)writes the
undofile or needs to sync the swapfile?

Best,
Christian
--
Alle großen Wahrheiten waren anfangs Blasphemien.
                -- George Bernard Shaw

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Elijah Griffin
In reply to this post by Tim Chase
Tim Chase wrote:
> :g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
> s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
> '\1\2\3','').'.txt'|s//\1,\2/|exec ".w!>>".s
> which works.  But for some reason, it is *painfully* slow on my
> machine.

Just do one write.

:v/"creditcard":"[0-9][0-9-]*"/d|%s!,*"\([a-z][a-z]*\)":!;\1=!g|%s,^{;,,|%s/},*$//|%s,\(timestamp="....\)-\(..\)-\(..\)[^"]*,\1\2\3,|%s!$!;echo '"'"$name"'"'",$creditcard" >> $timestamp.csv!|w ! /bin/sh -

That will probably work in ordinary vi, but my copy of nvi was unhappy.
I didn't try to figure out why. But I did prove to myself it works with
slight editing in ed. ("ed is the standard editor.")

v/"creditcard":"[0-9][0-9-]*"/d
1,$s!,*"\([a-z][a-z]*\)":!;\1=!g
1,$s,^{;,,
1,$s/},*$//
1,$s,\(timestamp="....\)-\(..\)-\(..\)[^"]*,\1\2\3,
1,$s!$!;echo '"'"$name"'"'",$creditcard" >> $timestamp.csv!
w data.json.sh
! /bin/sh data.json.sh

The fix for taking hyphens out of the credit card number should be
obvious, I didn't see any requirement to do that there, so I didn't.

I tried to post my solution to the dev.to site, but it wouldn't let me
log in.

Elijah

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Elijah Griffin
In reply to this post by Tim Chase
Tim Chase wrote:
> :g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
> s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
> '\1\2\3','').'.txt'|s//\1,\2/|exec ".w!>>".s
> which works.  But for some reason, it is *painfully* slow on my
> machine.

Just do one write.

:v/"creditcard":"[0-9][0-9-]*"/d|%s!,*"\([a-z][a-z]*\)":!;\1=!g|%s,^{;,,|%s/},*$//|%s,\(timestamp="....\)-\(..\)-\(..\)[^"]*,\1\2\3,|%s!$!;echo '"'"$name"'"'",$creditcard" >> $timestamp.csv!|w ! /bin/sh -

That will probably work in ordinary vi, but my copy of nvi was unhappy.
I didn't try to figure out why. But I did prove to myself it works with
slight editing in ed. ("ed is the standard editor.")

v/"creditcard":"[0-9][0-9-]*"/d
1,$s!,*"\([a-z][a-z]*\)":!;\1=!g
1,$s,^{;,,
1,$s/},*$//
1,$s,\(timestamp="....\)-\(..\)-\(..\)[^"]*,\1\2\3,
1,$s!$!;echo '"'"$name"'"'",$creditcard" >> $timestamp.csv!
w data.json.sh
! /bin/sh data.json.sh

The fix for taking hyphens out of the credit card number should be
obvious, I didn't see any requirement to do that there, so I didn't.

I tried to post my solution to the dev.to site, but it wouldn't let me
log in with Firefox (nothing happened when pushing the github button).
I did not even try to login with lynx.

Elijah

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Tim Chase
In reply to this post by Christian Brabandt
On 2017-11-14 22:41, Christian Brabandt wrote:

> > > Also does it work better if you explicitly use e.g.
> > > writefile('', 'a')?  
> >
> > Much faster!
> >
> > :g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
> > s=substitute(getline('.'),
> > '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*','\1\2\3','').'.txt'|s//\1,\2/|call
> > writefile([getline('.')], s, 'a')
> >
> >
> > runs in about the same time as the "echo" version or the "append
> > it to a list" version (i.e., one second or less).  
>
> I am puzzled now. Is that buffer loaded? Perhaps Vim (re-)writes
> the undofile or needs to sync the swapfile?

I'm unsure about what is happening under the covers, but it's
consistent if all I do is

  $ vim -u NONE data.json
  :g/...   " my initial lengthy :g command

with no syntax highlighting, no changes to the default environment.
It's about 5000 lines that get written, based on my rough wall-clock
timing, it's writing about 10 lines/second with the ".w!>>" version.
Meanwhile, the writefile() version is writing closer to 5000
lines/second.

-tim


--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Tim Chase
In reply to this post by Elijah Griffin
On 2017-11-14 19:04, Eli the Bearded wrote:
> Just do one write.

Yeah, I've come up with multiple multi-step solutions and the
solution I came up with *works*, it's just surprisingly slow for
something that can execute in around a second if slightly reworded
(see elsewhere on this thread where Christian recommends using
writefile() instead of ":.w>>")

> But I did prove to myselfit works with slight editing in ed.
> ("ed is the standard editor.")

As the loony who maintains the @ed1conf twitter account, I'm pleased
to see ed(1) popping up as a potential solution to the challenge. :-)

> I tried to post my solution to the dev.to site, but it wouldn't let
> me log in with Firefox (nothing happened when pushing the github
> button). I did not even try to login with lynx.

Yeah, their logins require 3rd-party cookies and JavaScript enabled
for the OAUTH authentication, so I don't often go to the hassle of
logging in there, instead sticking to directly posting/replying on
Twitter.  I can almost guarantee failure in lynx/links/elinks/w3m
without even trying.

-tim



--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Dominique Pellé
In reply to this post by Erik Falor
Erik Falor <[hidden email]> wrote:

> On Mon, Nov 13, 2017 at 09:33:49PM +0100, Christian Brabandt wrote:
>>
>> On So, 12 Nov 2017, Tim Chase wrote:
>>
>> > Taking on the challenge listed here
>> >
>> > https://dev.to/jorinvo/csv-challenge-1al
>> >
>> > it provides a .json file link to mung into date-named files (never
>> > mind that these happen to all be the same date), I came up with this
>> > vistrace -f  -e open,close,read,write -otrace.log ./vim  -u NONE data.json  -S old_engine.vimm solution:


This is how long it takes on my x86_64 xubuntu-16.04 machine
with SSD, using vim-8.0.1298 (huge)

$ cat old_engine.vim
set regexpengine=1
silent g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
'\1\2\3','').'.txt'|s//\1,\2/|exec ".w!>>".s
q!

$ cat new_engine.vim
set regexpengine=2
silent g/.*name":"\([^"]*\)".*card":"\([^"]*\)".*/let
s=substitute(getline('.'), '.*stamp":"\(\d\+\)-\(\d\+\)-\(\d\+\).*',
'\1\2\3','').'.txt'|s//\1,\2/|exec ".w!>>".s
q!

$ time ./vim -u NONE data.json  -S new_engine.vim
real    0m15.182s
user    0m1.652s
sys    0m0.712s

$ time ./vim -u NONE data.json  -S old_engine.vim
real    0m14.363s
user    0m0.972s
sys    0m0.600s


Where data.json is found at https://dev.to/jorinvo/csv-challenge-1al

While Vim is running, it's only uses ~ 10% of the CPU.
So it's not CPU bound.

Using...

$ strace -f  -e open,close,read,write,fsync -otrace.log \
    ./vim  -u NONE data.json  -S old_engine.vim

I see that Vim keeps opening, writing, closing, opening, writing, closing (etc)
the file 20150425.txt. It only writes a few bytes at at time (between
~30 and ~40 bytes).  We also keep opening/closing directory ".":

...snip...
4753  open(".", O_RDONLY)               = 8
4753  close(8)                          = 0
4753  open("20150425.txt", O_WRONLY|O_CREAT|O_APPEND, 0664) = 8
4753  write(8, "Lyla Schultz IV,1212-1221-1121-1"..., 36) = 36
4753  fsync(8)                          = 0
4753  close(8)                          = 0
4753  open(".", O_RDONLY)               = 8
4753  close(8)                          = 0
4753  open("20150425.txt", O_WRONLY|O_CREAT|O_APPEND, 0664) = 8
4753  write(8, "Ricardo Durgan,1234-2121-1221-12"..., 35) = 35
4753  fsync(8)                          = 0
4753  close(8)                          = 0
4753  open(".", O_RDONLY)               = 8
4753  close(8)                          = 0
4753  open("20150425.txt", O_WRONLY|O_CREAT|O_APPEND, 0664) = 8
4753  write(8, "Barton Graham,1212-1221-1121-123"..., 34) = 34
4753  fsync(8)                          = 0
4753  close(8)                          = 0

etc. (many other open/write/close like this)

Running this command without filtering syscalls, I get more details
of the repeating open/write/close/fsync calls:

$ strace -f -otrace.log ./vim -u NONE data.json-S old_engine.vim

...snip...
4560  getcwd("/home/pel/sb/vim/src", 4096) = 21
4560  stat("/home/pel/sb/vim/src/20150425.txt", {st_mode=S_IFREG|0664, st_size=3029496, ...}) = 0
4560  open(".", O_RDONLY)               = 8
4560  fchdir(8)                         = 0
4560  chdir("/home/pel/sb/vim/src")     = 0
4560  getcwd("/home/pel/sb/vim/src", 4096) = 21
4560  fchdir(8)                         = 0
4560  close(8)                          = 0
4560  stat("20150425.txt", {st_mode=S_IFREG|0664, st_size=3029496, ...}) = 0
4560  stat("/home/pel/sb/vim/src/20150425.txt", {st_mode=S_IFREG|0664, st_size=3029496, ...}) = 0
4560  readlink("20150425.txt", 0x7ffef493bd60, 4095) = -1 EINVAL (Invalid argument)
4560  stat(".20150425.txt.swp", 0x7ffef493ccf0) = -1 ENOENT (No such file or directory)
4560  stat("20150425.txt", {st_mode=S_IFREG|0664, st_size=3029496, ...}) = 0
4560  access("20150425.txt", W_OK)      = 0
4560  getxattr("20150425.txt", "system.posix_acl_access", 0x7ffef493cb90, 132) = -1 ENODATA (No data available)
4560  stat("20150425.txt", {st_mode=S_IFREG|0664, st_size=3029496, ...}) = 0
4560  open("20150425.txt", O_WRONLY|O_CREAT|O_APPEND, 0664) = 8
4560  write(8, "Keeley Bosco,1228-1221-1221-1431"..., 33) = 33
4560  fsync(8)                          = 0
4560  close(8)                          = 0
4560  chmod("20150425.txt", 0100664)    = 0
4560  setxattr("20150425.txt", "system.posix_acl_access", "\2\0\0\0\1\0\6\0\377\377\377\377\4\0\6\0\377\377\377\377 \0\4\0\377\377\377\377", 28, 0) = 0
4560  recvmsg(5, 0x7ffef493dda0, 0)     = -1 EAGAIN (Resource temporarily unavailable)
4560  recvmsg(5, 0x7ffef493dda0, 0)     = -1 EAGAIN (Resource temporarily unavailable)
4560  poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout)
4560  select(6, [0 3 5], [], [0 3], {0, 0}) = 0 (Timeout)
4560  getcwd("/home/pel/sb/vim/src", 4096) = 21
4560  stat("/home/pel/sb/vim/src/20150425.txt", {st_mode=S_IFREG|0664, st_size=3029529, ...}) = 0
4560  open(".", O_RDONLY)               = 8
4560  fchdir(8)                         = 0
4560  chdir("/home/pel/sb/vim/src")     = 0
4560  getcwd("/home/pel/sb/vim/src", 4096) = 21
4560  fchdir(8)                         = 0
4560  close(8)                          = 0
4560  stat("20150425.txt", {st_mode=S_IFREG|0664, st_size=3029529, ...}) = 0
4560  stat("/home/pel/sb/vim/src/20150425.txt", {st_mode=S_IFREG|0664, st_size=3029529, ...}) = 0
4560  readlink("20150425.txt", 0x7ffef493bd60, 4095) = -1 EINVAL (Invalid argument)
4560  stat(".20150425.txt.swp", 0x7ffef493ccf0) = -1 ENOENT (No such file or directory)
4560  stat("20150425.txt", {st_mode=S_IFREG|0664, st_size=3029529, ...}) = 0
4560  access("20150425.txt", W_OK)      = 0
4560  getxattr("20150425.txt", "system.posix_acl_access", 0x7ffef493cb90, 132) = -1 ENODATA (No data available)
4560  stat("20150425.txt", {st_mode=S_IFREG|0664, st_size=3029529, ...}) = 0
4560  open("20150425.txt", O_WRONLY|O_CREAT|O_APPEND, 0664) = 8
4560  write(8, "Rubye Jerde,1228-1221-1221-1431\n", 32) = 32
4560  fsync(8)                          = 0
4560  close(8)                          = 0
4560  chmod("20150425.txt", 0100664)    = 0
4560  setxattr("20150425.txt", "system.posix_acl_access", "\2\0\0\0\1\0\6\0\377\377\377\377\4\0\6\0\377\377\377\377 \0\4\0\377\377\377\377", 28, 0) = 0
4560  recvmsg(5, 0x7ffef493dda0, 0)     = -1 EAGAIN (Resource temporarily unavailable)
4560  recvmsg(5, 0x7ffef493dda0, 0)     = -1 EAGAIN (Resource temporarily unavailable)
4560  poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout)
4560  select(6, [0 3 5], [], [0 3], {0, 0}) = 0 (Timeout)
4560  getcwd("/home/pel/sb/vim/src", 4096) = 21
4560  stat("/home/pel/sb/vim/src/20150425.txt", {st_mode=S_IFREG|0664, st_size=3029561, ...}) = 0
...snip...

Notice that it's use fsync() after each small write to file "20150425.txt".

Using my attached io.pl script which summarizes the trace.log file
and shows where I/Os come from, I get this:

$ strace -f -e open,close,read,write,fsync -otrace.log \
    ./vim -u NONE data.json -S old_engine.vim

$ io.pl < trace.log
read_bytes   #read  write_bytes  #write  #open  #fsync  filename
----------   -----  -----------  ------  -----  ------  --------
   1612897      27          0       0       2       0  data.json
    135992      35          0       0       2       0  /usr/share/X11/locale/locale.alias
     36864       9          0       0       1       0  /usr/share/X11/locale/locale.dir
     16720       8          0       0       4       0  /home/pel/.ICEauthority
      4250       3          0       0       1       0  /usr/share/X11/locale/en_US.UTF-8/XLC_LOCALE
      3361       2          0       0       1       0  /lib/terminfo/x/xterm
      3171      16        216       7       1       0  /usr/share/locale/locale.alias
       832       1          0       0       1       0  /lib/x86_64-linux-gnu/libnss_nis.so.2
...snip many files with little amount of I/Os...
         0       0          0       0       1       0  .data.json.swx
         0       0     179281    5004    5004    5004  20150425.txt
         0       0          0       0       5       0  /etc/ld.so.cache
         0       0          0       0    5004       0  .
         0       0      16384       4       2       0  .data.json.swp
         0       0          0       0       1       0  /usr/lib/locale/locale-archive
----------   -----  -----------  ------  ------  -----  TOTAL
   1883068     191     195881    5015   15121    5004

As highlighted in red, notice that we only write 179,281 bytes to file
"20150425.txt" but we open/write/close/fsync 5004 times.
That repeated I/O patterns kills performance, especially because
of the frequent fsync().

We also read 1,612,897 bytes from data.json, but that should be
fast since we do only 27 read and opened that file only twice
according to output of io.pl. Vim reads file deta.json by chunks
of 64 KB. 1,612,897 bytes is exactly the file size of data.json.

Maybe we can change vim to avoid the constant open/write/close/fsync
on file "20150425.txt" which should speed it up greatly.

Regards
Dominique

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Dominique Pellé
Dominique Pellé <[hidden email]> wrote:
 

Using my attached io.pl script which summarizes the trace.log file
and shows where I/Os come from, I get this:

$ strace -f -e open,close,read,write,fsync -otrace.log \
    ./vim -u NONE data.json -S old_engine.vim

$ io.pl < trace.log
read_bytes   #read  write_bytes  #write  #open  #fsync  filename
----------   -----  -----------  ------  -----  ------  --------
   1612897      27          0       0       2       0  data.json
    135992      35          0       0       2       0  /usr/share/X11/locale/locale.alias
     36864       9          0       0       1       0  /usr/share/X11/locale/locale.dir
     16720       8          0       0       4       0  /home/pel/.ICEauthority
      4250       3          0       0       1       0  /usr/share/X11/locale/en_US.UTF-8/XLC_LOCALE
      3361       2          0       0       1       0  /lib/terminfo/x/xterm
      3171      16        216       7       1       0  /usr/share/locale/locale.alias
       832       1          0       0       1       0  /lib/x86_64-linux-gnu/libnss_nis.so.2
...snip many files with little amount of I/Os...
         0       0          0       0       1       0  .data.json.swx
         0       0     179281    5004    5004    5004  20150425.txt
         0       0          0       0       5       0  /etc/ld.so.cache
         0       0          0       0    5004       0  .
         0       0      16384       4       2       0  .data.json.swp
         0       0          0       0       1       0  /usr/lib/locale/locale-archive
----------   -----  -----------  ------  ------  -----  TOTAL
   1883068     191     195881    5015   15121    5004



Oops, I forgot to attach my io.pl script used to produce
above I/O summary.  Here it is attached this time.

Dominique

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Christian Brabandt
In reply to this post by Dominique Pellé

On Mi, 15 Nov 2017, Dominique Pellé wrote:

> As highlighted in red, notice that we only write 179,281 bytes to file
> "20150425.txt" but we open/write/close/fsync 5004 times.
> That repeated I/O patterns kills performance, especially because
> of the frequent fsync().
>
> We also read 1,612,897 bytes from data.json, but that should be
> fast since we do only 27 read and opened that file only twice
> according to output of io.pl. Vim reads file deta.json by chunks
> of 64 KB. 1,612,897 bytes is exactly the file size of data.json.
>
> Maybe we can change vim to avoid the constant open/write/close/fsync
> on file "20150425.txt" which should speed it up greatly.

Thanks for this nice analysis. It is probably the fsync call that is
slowing Vim down. We can avoid the fsync by disabling the 'fsync'
option. Also we might want to disable the writebackup option just in
case it matters. And finally, when a file is written in a different
encoding, Vim will try to check if conversion is safe by first trying to
convert the buffer contents to the fileencoding before writing the file.
That might make also a difference when encoding differs from the file
encoding.

Perhaps it makes sense to skip fsyncing while being busy in a `:g`
command. Tim, does this patch make a difference?

diff --git a/src/fileio.c b/src/fileio.c
index d991822c3..eb626a675 100644
--- a/src/fileio.c
+++ b/src/fileio.c
@@ -4731,7 +4731,7 @@ restore_backup:
         * work (could be a pipe).
         * If the 'fsync' option is FALSE, don't fsync().  Useful for laptops.
         */
-       if (p_fs && fsync(fd) != 0 && !device)
+       if (p_fs && !global_busy && fsync(fd) != 0 && !device)
        {
            errmsg = (char_u *)_("E667: Fsync failed");
            end = 0;

Christian
--
Was auch immer, du mich auch.

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Vim surprisingly slow?

Tim Chase
On 2017-11-15 08:25, Christian Brabandt wrote:
> On Mi, 15 Nov 2017, Dominique Pellé wrote:
> > As highlighted in red, notice that we only write 179,281 bytes to
> > file "20150425.txt" but we open/write/close/fsync 5004 times.
> > That repeated I/O patterns kills performance, especially because
> > of the frequent fsync().
[snip]
> > Maybe we can change vim to avoid the constant
> > open/write/close/fsync on file "20150425.txt" which should speed
> > it up greatly.  

However, my understanding is that the writefile() method should be
doing the same thing (open, append, close) and that's as fast as I
expect.  Though I could be wrong and writefile() might internally
cache the file handle.

> Thanks for this nice analysis. It is probably the fsync call that
> is slowing Vim down. We can avoid the fsync by disabling the
> 'fsync' option.

Does the writefile() method does an fsync() too?  If not, it's a
strong indicator that the fsync() may be part of the guilty slowness.

If the writefile() version does an fsync() we may be barking up the
wrong tree.

I'll test the patch later today when I'm not about to run out the
door.

Thanks!

-tim



--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
12