Watchers runs tests several times on Linux #495

Closed
alexshuhin opened this Issue Oct 9, 2013 · 31 comments

Projects

None yet

10 participants

@alexshuhin

I have problem with rails4 + ruby2.0 + guard 2.0.3 + guard-rspec 3.1.0, the problem is good described at http://stackoverflow.com/questions/19271319/guard-runs-specs-three-times

btw, i can't reproduce it on MacOS

@rymai
Guard member

It's due to the way vim saves the file: https://github.com/guard/guard/wiki/Analysis-of-inotify-events-for-different-editors#vim

I believe this is a guard-rspec implementation issue. We could replace run_on_changes with run_on_modifications here: https://github.com/guard/guard-rspec/blob/master/lib/guard/rspec.rb#L48 but specs wouldn't run when new files are really created (i.e. not on a vim save).

@thibaudgg what do you think?

@erpe

i can confirm that editing files with vim, gedit on linux results as reported on stackoverflow.
when changing files e.g. in eclipse this behavior does not occur.

@thibaudgg
Guard member

Yeah replacing replace run_on_changes with run_on_modifications is a good idea, I'll change it in 4.0.0 release of Guard::RSpec (ready soon).

There's no way of changing how vim saves files?

@rymai
Guard member

Closing this issue since this will be fixed in guard-rspec.

@rymai rymai closed this Oct 10, 2013
@sch0rsch sch0rsch added a commit to sch0rsch/guard-test that referenced this issue Nov 2, 2013
@sch0rsch sch0rsch Run on modifications instead of changes
Due to the way vim saves files the corresponding tests
are run three times. To prevent this use run_on_mondifications
instead of run_on_changes.

See also:
* guard/guard#495
* jejacks0n/guard-teaspoon#18
e66a93a
@rymai rymai added a commit to guard/guard-shell that referenced this issue Nov 4, 2013
@rymai rymai Run on modifications instead of changes
Due to the way vim saves files the corresponding tests
are run three times. To prevent this use
run_on_modifications instead of run_on_changes.

See also:
* guard/guard#297
* guard/guard#495
d150c6e
@rymai rymai added a commit to guard/guard-shell that referenced this issue Nov 4, 2013
@rymai rymai Run on modifications instead of changes
Due to the way vim (or other editors) saves files,
guard-shell executes twice or three times. To prevent this,
use run_on_modifications instead of run_on_changes.

See also:
* guard/guard#297
* guard/guard#495
60b45c8
@killphi killphi added a commit to killphi/guard-yard that referenced this issue Dec 1, 2013
@killphi killphi fix vim file saving behavior
run only once
guard/guard#495
7512072
@jovon

I'm having the same issue using Sublime Text 2 on Linux with sinatra (1.4.4), guard-rspec (4.2.0), guard-spork (1.5.1) and ruby (2.0).

@jovon
@jovon
@thibaudgg
Guard member

@jovon do you run guard with bundler bundler exec guard? I would recommend to remove Spork and use something more up-to-date.

@killphi

@jovon This is a known problem in several "older" guard plugins.

I have an open pull request on guard-spork (guard/guard-spork#124) that addresses this issue.

@PaBLoX-CL

I'm still having problems saving with vim,

22:54:49 - DEBUG - Hook :run_on_changes_end executed for Guard::Rails
22:54:49 - DEBUG - Trying to run Guard::Rails#run_on_removals with ["config/application.rb", "config/4913"]
22:54:49 - DEBUG - Hook :run_on_changes_begin executed for Guard::Rails
22:54:49 - INFO - Restarting Rails...

Of course it runs twice, but I don't understand where does that "config/4913" comes from.

@pjump

Hi. I'm new to Guard, currently using it on Mint 13 (~Ubuntu 12.04) while following the http://ruby.railstutorial.org/ , and I'm also experiencing this issue. With a save in vim, I get my tests run 3 times, 2 times if I save my watched file in pluma or gedit. Wouldn't it be possible just ignore the differences between those editors by simply merging multiple adjacent hook invocations received within a relatively small time period? (Say if file A causes a test run, ignore any events on that file for, say, 1 second?)

@thibaudgg
Guard member

Related to #587

@redterror redterror added a commit to redterror/guard-migrate that referenced this issue Apr 30, 2014
@redterror redterror use run_on_modifications instead of run_on_changes to avoid multiple …
…runs after saving files with VIM. See: guard/guard#495
4e80422
@SeanLuckett

I came to this issue because guard was running tests multiple times. It turned out my Guardfile was getting appended instead of replaced when I ran guard init rspec, so it was running 4 'instances' of guard in one. Check your Guardfile if this is happening to you.

@PaBLoX-CL

This still happens when using various linux editors, is there some sort of workaround? :c

@e2
e2 commented Sep 23, 2014

@PaBLoX-CL - first work out which of the causes is affecting you. Overall, Linux editors should work great with newer versions of Listen (used by guard).

Check out: https://github.com/guard/listen#issues-and-troubleshooting for the LISTEN_GEM_DEBUGGING variable.

Also, run guard with the '-d' option to check and make sure you're using run_on_modifications, and not any of the other run_on_* methods.

@PaBLoX-CL

Ok, the problem has to do that vim creates a 4913 file to test if the directory is writable. I sent an email to the vim-dev lists.

https://gist.github.com/PaBLoX-CL/097658d9e242cd34929b

What I don't get, is that 4913 isn't matched by any regex in the guardfile, so why it would be ran again?

After researching for a bit, it seems that the correct way to deal with vim file notifications it's using IN_CLOSE_WRITE :/.

@e2
e2 commented Oct 1, 2014

@PaBLoX-CL - handling editor files is a bit complex.

Overall, listen on Linux watches directories and gets all events on that directory, and then uses ignore filters to discard unimportant files.

The special Vim file: 4913 is ignored by default, see:
https://github.com/guard/listen/blob/master/lib/listen/silencer.rb#L33

Everything you're seeing though are just internal processing of events. The line:

listen: final changes: {:modified=>["/home/pablo/code/rails/resp/spec/controllers/encounters_controller_spec.rb"], :added=>[], :removed=>[]}

... is what actually triggers the change - so everything looks ok, because you edited encounters_controller_spec.rb and a "modified" event was triggered (the 4913 was successfully ignored).

(if you set LISTEN_GEM_DEBUGGING to '1', you'll see only the "info" messages, while '2' shows lots of info about internals you probably don't care about in this specific case)

@PaBLoX-CL

@e2 I'm sorry, you are right, I should have looked into the source :c. What I don't understand is why then they still ran twice...

https://asciinema.org/a/12630 (it has to be watched on full screen)

@e2
e2 commented Oct 2, 2014

TL;DR for others - if you have the same problem, you may need to increase listen's wait_for_delay time using guard's -y option.

@PaBLoX-CL - no problem, I'm just trying to help work this out.

Just to confirm: do the tests still run twice if instead of editing encounters_controller_spec.rb you do e.g. touch spec/controllers/encounters_controller_spec.rb?

I'm guessing your wait_for_delay option might be too small if you have a lot of callbacks/plugins running in your editor when saving - like formatting, checking syntax, repository status (guard has a '-y' option to help with this, e.g. guard -y 0.4)

Here's why:

  1. This line:
    https://gist.github.com/PaBLoX-CL/097658d9e242cd34929b#file-gistfile1-txt-L14
    shows Vim created the new file (during saving) at: 14:02:07.091932

  2. After 0.1 seconds: listen started processing collected events: https://gist.github.com/PaBLoX-CL/097658d9e242cd34929b#file-gistfile1-txt-L19

  3. At 14:02:07.327380, a :close_write occured on the file

So it looks like saving a file on your setup takes: 0.24 seconds (between creating the 4193 file and the final :attrib event), so running guard -y 0.3 should do the trick.

Let me know if this helps and or if there's anything I could've done to help you discover this sooner (it's a bit tricky, although there probably should be a troubleshooting section in Guard for this).

@PaBLoX-CL

Just to confirm: do the tests still run twice if instead of editing encounters_controller_spec.rb you do e.g. touch spec/controllers/encounters_controller_spec.rb?

No, they don't ran twice, that doesn't happen with the others editors either.

So it looks like saving a file on your setup takes: 0.24 seconds (between creating the 4193 file and the final :attrib event), so running guard -y 0.3 should do the trick.

Yep, I have noticed that indeed vim is taking some time to save the file, I have tried to augment the -y value before with no success, but I only tried with small values. It works fine with values around 0.7 (or even 0.9 when compiling a nanoc site). I tried running vanilla vim, and TADÁ, it doesn't run twice. So, you are right, the editor it's the problem. I'm gonna start looking around why it's taking so long to save the file (but I suspect whom are the culprits).

Thanks again and sorry for the noise. I should have tried before running vim with no plugins. In exchange, I'll add a little note in the wiki (if that's okay for you). :D

@e2
e2 commented Oct 3, 2014

Don't worry - I prefer to get to the bottom of issues like this, because then I can consider how to prevent them.

At one time I thought about warning when changes happen during callback (with debugging option on, of course) - just never got to implementing it (I suspected too few people were bitten by it - especially with SSD drives being more common nowadays).

I've also spent a lot of time dealing with timing issues in the acceptance tests in listen (because every adapter works differently by design) - so I didn't mind looking into this closer.

I even thought of changing the default, but that would cause problems for people using Listen to sync files with virtual machines (they want a fast response over "correctness" instead).

@e2
e2 commented Oct 3, 2014

👍 for any changes in the docs that could be helpful

I was thinking about a separate "troubleshooting" section for guard/listen - so people could discover causes of issues on their own, instead of having to wait for a lengthy back-and-forth reply.

@PaBLoX-CL

Hm, this is very strange. I have removed every plugin from vim, and also every option. Just a plain vimrc and this still happens. The only option that gets "changed" with having an empty vimrc is set nocompatible. So even with all my plugins loaded, if I change to set compatible, I can't reproduce the error anymore.

https://asciinema.org/a/12656

I have also realized as I posted in the vim-dev mail list → https://groups.google.com/d/topic/vim_dev/NJlpPL4_a1Y/discussion, with set compatible the 4913 file doesn't get created. That's why I believed it has something to do.

 ❯❯❯ guard -P nanoc
12:53:51 - INFO - Guard is using NotifySend to send notifications.
12:53:51 - INFO - Guard is using TerminalTitle to send notifications.

12:53:53 - INFO - Compilation succeeded.
12:53:53 - INFO - Guard is now watching at '/home/pablo/code/web/pablox-cl.github.io'
[1] Nanoc guard(main)> 
12:54:00 - INFO - Compilation succeeded.

12:54:02 - INFO - Compilation succeeded.
[1] Nanoc guard(main)> # now we do set compatible in vim and save the document
[1] Nanoc guard(main)> 
12:54:59 - INFO - Compilation succeeded.
[1] Nanoc guard(main)> # ^ THIS
@e2
e2 commented Oct 3, 2014

Set the LISTEN_GEM_DEBUGGING=2, and post the output so we check the timings.

Also, vim has a lot of settings for backup/temp files created during saving - so you might want to check those as well.

You might also want to make sure your filesystem is mounted with a noatime option to prevent unnecessary writes.

With strace you could check the timing of each system call - to see if the filesystem is slow (e.g. if you're using encryption).

Without details in timing it's hard to know what needs fixing.

@PaBLoX-CL

Set the LISTEN_GEM_DEBUGGING=2, and post the output so we check the timings.

Here it is, I posted three scenarios, the first one, which ran twice, the second saving the file after using set compatible in vim, and the last one, its using set compatible from the beginning of my .vimrc.

https://gist.github.com/PaBLoX-CL/33c76b13a44792611495

Also, vim has a lot of settings for backup/temp files created during saving - so you might want to check those as well.

I believe these are the most relevant ones, but I have set them outside the working dir.

set undodir=~/.vim/.cache/undo
set backup
set backupdir=~/.vim/.cache/backup
set directory=~/.vim/.cache/swap
set noswapfile

You might also want to make sure your filesystem is mounted with a noatime option to prevent unnecessary writes.

I'm using a btrfs file system (dunno it has something to do)

/dev/sda7 on /home type btrfs (rw,noatime,compress=lzo,ssd,discard,space_cache,autodefrag,inode_cache)

With strace you could check the timing of each system call - to see if the filesystem is slow (e.g. if you're using encryption).

Ok, here are 4 scenarios:

  1. set nocompatible
    • strace -c -p
    • strace -p
  2. set compatible
    • strace -c -p
    • strace -p

https://gist.github.com/PaBLoX-CL/468ce627efbd1a19069a

The only thing it caught my eye, it's the difference in some system calls, the former:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
65.92 0.004000 1000 4 clone
32.96 0.002000 2000 1 fsync
1.04 0.000063 3 19 wait4
0.08 0.000005 0 76 rt_sigaction
0.00 0.000000 0 65 39 read
0.00 0.000000 0 48 write

while the latter (set compatible)

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
98.46 0.003000 750 4 clone
1.54 0.000047 3 18 wait4
0.00 0.000000 0 51 38 read
0.00 0.000000 0 17 write
@e2
e2 commented Oct 5, 2014

Yeah, it's taking a whopping 2.1 seconds to complete saving the file - strange.

btrfs's sync used to be tragically slow in the past, but from the above strace output, it looks like it doesn't matter (SSD makes it 0.002s - not nearly enough to cover the 2 second difference).

So we can rule out hardware and filesystem (though from your record-build time it does seem like you have a lot of files in that directory or traversing it may be an issue. Also, you have compression enabled in btrfs - you might want to try disabling it temporarily to check if that changes anything - btrfs saves compression info in extents, so this temporary disabling should have no permanent effect).

I'm guessing it could be a combination of a slow terminal+tmux+graphics card ... - try doing the save in a tiny window to avoid graphics/terminal refreshing. Try running find on a huge directory twice (the first time could take a few seconds due before fs is cached, by the second run should finish in a fraction of a second - without "waiting" for the terminal to draw).

(You could also try running everything from an ssh session, so drawing to the screen/terminal isn't an issue). I use urxvt in client/server mode, because for a UTF-8 compatible terminal it's quite fast, even with pseudo-transparency. The font could also be an issue if you're using something too fancy (I use Inconsolata).

You could also try using ltrace in case something CPU-intensive shows up.

Otherwise, I'm out of ideas.

@PaBLoX-CL

I found what the problem was. It was very simple, so I'm sorry for all the noise (the bright side is that I learnt quite a lot about listen/guard internals and general inotify information).

The problem was the set backup in vim. I didn't realized that turning on set compatible turned it off, so that's why it was working when setting it. On the other side, when doing binary search through my vimrc, I was setting the backup in two parts of the file, so I never realized I never trully disabled it.

I still need to set -y parameter, but now with lower values. It makes sense though, because a lot of plugins ran when BufWrite (like syntastic for instance).

Thanks again for your time and disposition, if you ever come to Chile, tell me so I can invite you a or a 🍺 :).

@e2
e2 commented Nov 14, 2014

so I'm sorry for all the noise

On the contrary! I'm glad to help! It's so much more fun when development tools work as expected - so I'm always looking for ways to prevent issues like this.

if you ever come to Chile, tell me so I can invite you a  or a 🍺  :)

Sure! Chile seems like such a beautiful place to visit.

@PaBLoX-CL

Oh, just to close this "properly":

I just found that the problem was setting the backupdir option vim. Not even the backup option!.

set backup " works (immediate save)
set nobackup " works (immediate save)
set backupdir=~/.vim/.backup " saving the file takes 2 to 3 seconds 

I dunno why this happens, and I will ask in the vim list, but I still drop it here, in case some other confused person ran into this. :P

@e2
e2 commented Nov 18, 2014

Probably best to run strace to see the timings first - to work out between which syscalls the delay happens. Then consult the vim source to see what could be going on in between.

Then, it would probably be easier to find the culprit.

Personally, I use vim's patchmode option - the only downside is I get lots of *.orig files (or whatever extension you choose) all over the place, but I've learn to live with them (adding them to ~/.gitignore, git clean, etc.).

It's like a backup done only the first time, and never again (until I remove the files again) - although it obviously makes no sense within a checked out repository. It does come useful if you're playing around e.g. with files within installed gems, and then you want to create a patch with the changes you've made to create a pull request, etc.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment