blocking parallel execution?

[tobowers]

Hi! Love the project. Really great work.

While working with the go IPLD library. I noticed real-world slow down in my app that looked like blocking behavior... up to 200-600ms for a simple action to complete.

I eventually narrowed it down to a line in the IPLD cbornode library and then continued down the rabbit hole into refmt. ipfs/go-ipld-cbor#37

It seems like individual encoding/decoding is fast, but that somehow decoding can block other decodes. I haven't yet delved into the internals of refmt to check this out.

Here's a failing test with 160ms decodes. It has 10k parallel processes, but in my real-world app I had hundreds but more complicated objects showing the same behavior (or longer times).

https://gist.github.com/tobowers/d7a0e05d68459da54808a65c145c50d5

[warpfork]

That sounds really weird. I'll take a look. FWIW, there are no mutexes at all in refmt -- I've intentionally kept them out, with the idea that if the application needs them, then everything can be sync.Pool'd at higher level and that should solve stuff -- so concurrency should be pretty transparent...

[tobowers]

I'm not a go-internals expert, but I was wondering if it was related to interfaces and reflection... and/or use of channels... but I'm not sure.

[warpfork]

I took your gist and ran with it a bit, and came up with this: https://gist.github.com/warpfork/ac63075a5d2996e011822423db7e2b1c

I don't think the parallelism is the problem here.

A reproducer with some of those more complicated objects might be worth trying to fabricate. And that's something I'd really like to merge more of also; the current benchmarks in the refmt repo are a little too narrow in what they exercise.

[tobowers]

Ok. Thanks for looking! Let me take my real-world app and see if I can't make a simpler repo that's not as simple as that :)

[tobowers]

I know this is way too complicated for a repro... but it's what I have at hand that led me down this path... maybe it's only about go context switching... but: https://github.com/QuorumControl/encodeexplore

That will produce output for how long each decode took (encode doesn't seem to suffer the same problem).

There are occasional huge spikes:

INFO [07-17|14:20:27.608] decode                                   took=2.12226ms
INFO [07-17|14:20:27.608] decode                                   took=2.810995ms
INFO [07-17|14:20:27.608] decode                                   took=2.108842ms
INFO [07-17|14:20:27.609] decode                                   took=2.153836ms
INFO [07-17|14:20:27.609] decode                                   took=780.894544ms
INFO [07-17|14:20:27.610] decode                                   took=2.485473ms
INFO [07-17|14:20:27.610] decode                                   took=1.997425ms
INFO [07-17|14:20:27.611] decode                                   took=2.244557ms
INFO [07-17|14:20:27.611] decode                                   took=4.895766ms
INFO [07-17|14:20:27.611] decode                                   took=2.243713ms
INFO [07-17|14:20:27.611] decode                                   took=4.29352ms
INFO [07-17|14:20:27.611] decode                                   took=2.551357ms
INFO [07-17|14:20:27.612] decode                                   took=2.30946ms
INFO [07-17|14:20:27.613] decode                                   took=3.84674ms
INFO [07-17|14:20:27.613] decode                                   took=2.265534ms
INFO [07-17|14:20:27.613] decode                                   took=2.205228ms
INFO [07-17|14:20:27.613] decode                                   took=2.192477ms
INFO [07-17|14:20:27.613] decode                                   took=2.282205ms
INFO [07-17|14:20:27.615] decode                                   took=2.228272ms
INFO [07-17|14:20:27.615] decode                                   took=4.539288ms
INFO [07-17|14:20:27.615] decode                                   took=2.551364ms
INFO [07-17|14:20:27.615] decode                                   took=3.87301ms
INFO [07-17|14:20:27.615] decode                                   took=2.228045ms
INFO [07-17|14:20:27.616] decode                                   took=2.411149ms
INFO [07-17|14:20:27.616] decode                                   took=2.268814ms
INFO [07-17|14:20:27.616] decode                                   took=2.295646ms
INFO [07-17|14:20:27.617] decode                                   took=762.974013ms
INFO [07-17|14:20:27.617] decode                                   took=791.030098ms

[tobowers]

FWIW - switching the call to a time.Sleep(2 * time.Milisecond) does not have wild swings like that.

[warpfork]

Okay, I definitely have something to keep investigating there 🤔

[tobowers]

I know that's not ideal code to work with and it's nested go routines... let me know how I can help.