Spock hangs up Statamic on content save/reorder for... a while

[timichango]

Was having an issue with re-ordering entries within a collection taking a long time (18s+) to complete, as well as intermittent long waits to save content, fieldset configs, etc. — eventually determined (with help from Erin over on the Statamic Discord channel) that Spock was the culprit. Removing Spock from my addons returned save/reorder performance to nigh-immediate execution.

Erin's suspicion was that something's maybe not getting queued properly? Bug perhaps?

[jasonvarga]

Have you configured spock to run any non standard commands?

[timichango]

Nope — just the default options.

Here's a sample of what's going on in the logs (identifying info redacted):

[2019-01-07 11:15:11] dev.ERROR: Spock command exited unsuccessfully:
Command: git -c "user.name=*******" -c "user.email=*******" commit -m "Entry saved by *******"
Output:
On branch master
Your branch is up to date with '*******/Statamic/master'.

nothing to commit, working tree clean

Error: No error

As further context, more details that I've been able to ascertain:

• primarily seems to happen when saving reorder. There may be other repeatable contexts, but so far that's the main one I'm experiencing
• logs show the above error pattern whenever a reorder save is initiated. At first I suspected it might only happen when a save was initiated without actually altering the prior order (leading to a commit-attempt on an already up-to-date branch), but it seems to happen identically even if I do alter the order. Which is weird, because watching the git commits unfold around an actual order change, it's apparent that the commits are indeed happening as expected.
• I notice Spock winds up chucking out a unique commit for each file that gets renamed (with the order number) as part of a reorder — not sure if that's what's supposed to be happening, but it does seem pretty weird and unwieldy that, for example, reordering a group of 15 files results and saving that order results in up to 15 commits (assuming everything has a new order position being saved). Is this a bug? Is this inevitable? Either way it seems unintuitive and unexpected from a usage perspective.
• Actually... now that I think of it... Spock generates a bunch of the log messages I indicated above for each reorder/save: which leads me to wonder if the issue is related to Core resaving each file on a reorder/save, then Spock firing a commit for each file in the collection (since each was re-saved, changed or not), and then there being some latency involved with a subset of the single-file-commits failing (since there's no actual change to the repo), generating the subsequent "Up To Date / Error: No error" log messages, yada yada.

Thoughts?

[timichango]

If the last point above is actually what's going on, then it seems like there're maybe two issues afoot:

1. Should core re-save entries whose order is not being altered, during a re-order/save?
2. Should Spock initiate a commit for each file during a re-order, or should it commit the changes as a batch, after the re-order/save completes?

[jesseleite]

Looking into queue support. Also curious, which versions of both Statamic and Spock are you running?

[timichango]

The latestest I think — only been using both for ~two weeks-ish.

Statamic 2.11.3 2.11.4 / Spock 2.1.0 ...for specificity's sake :)

[jesseleite]

The next version of Spock should automatically queue commands, so if you have QUEUE_DRIVER=redis setup with a php please queue:listen worker, users won't feel the pain if git hangs up for whatever reason.

That said, I'm still unclear what's happening to cause such long wait on re-order. How does everything perform when editing a single page, etc.?

[jesseleite]

@timichango I notice you've mentioned the entry re-ordering thing here which is valid, but a separate issue. Created a new issue for that specifically #33 🙂

[timichango]

"That said, I'm still unclear what's happening to cause such long wait on re-order. How does everything perform when editing a single page, etc.?"

Reckon you've already discerned the answer to this, given the new issue #33 that you just opened, but in my case I believe the latency is down to the fact that during a re-order, only a handful of entries (or none at all, if no changes have been made but a re-order-->save-order is initiated anyways) wind up being renamed (thus changed, in git's eyes), while all wind up being re-saved anyways — and since it's firing one commit per entry re-save, those commits that correspond to a no-change situation wind up coming back with that weird error: no error message, indicating that the repo's already up-to-date. Which seems to take a sec to round-trip. Multiply that round-trip latency by the number of entries in a collection view that are touched in any way by the re-order, and you've got your total hang-up latency before the CP wakes up and takes you back to the main listing for that collection.

[timichango]

In Sublime, with the collection folder open, for example, I can watch all of the files get touched/renamed — while watching tail -f on the current log — and when the renaming/logging finally finishes chewing through all of the attempted commits, that's when the CP view starts responding again.

[timichango]

Which makes me wonder... can/should Spock check the repo's change status (relative to the file/perceived change it's trying to commit) before firing a commit? If no change, don't commit...

Like "is the repo changed? is/are the file/files related to this event in those changes? If yes to both: commit"

[jesseleite]

Reckon you've already discerned the answer to this, given the new issue #33 that you just opened, but in my case I believe the latency is down to the fact that during a re-order, only a handful of entries

No. Whether I re-order a few entries, or 30 entries, I can't reproduce the 18+ second hangtime you're facing. Still in the dark about what's causing that for you. I'd still like to figure out what's going on here, but I'm not convinced it's related to multiple commits specifically. Over here, I'm able to re-order 15 out of 30 entries, and Spock commits them all in well under 1 second 🤔

Again, we've implemented the ability to queue (via redis/etc.) Spock's event handling (likely coming in the next Spock release), so that the user won't feel any Spock-related lag. That's sidestepping the problem though. I'm still curious about the 18+ second hangtime, so I'll leave this issue open. Have a great weekend!

[timichango]

Hey man — I'll do some more testing, but I'm pretty sure that when there is a change to make to the repo when the commit gets fired, they complete super quickly. It's when there isn't an actual change to the repo, but a Statamic event fires a commit anyways, that things seem to get funky. Basically it seems like whenever Spock starts logging commit failures, things get s-l-o-w-w-w. For a bit anyways.

Watching the log with tail -f, you're not seeing it notch through each commit failure at like 1s+ per log message?

[timichango]

WAITASEC — do you have yours set to push automatically?

Maybe that's the exacerbating factor here...

You have a great weekend too! :)

[jesseleite]

Ah, that's it! A commit attempt (even with no changes to commit) is still quite fast, but pushing between each commit is slow because of having to connect to your remote.

#33 will indeed improve this immensely. However, we'll get the queue update out to you soon, which I'd still recommend setting up because even a single git push can take a second or three sometimes, and your users are still going to feel that lag.

[jesseleite]

Tagged Spock 2.2.0 with queueing (see docs on how to use) 🤘 Closing this issue, but will leave #33 open for when we have time to address that side of it.