Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

redesign worker GR lifetime to span lifetime of app instead of a new GR for each job #4

Closed
Tracked by #1
plastikfan opened this issue Aug 7, 2023 · 7 comments · Fixed by #9
Closed
Tracked by #1
Assignees
Labels
feature New feature or request

Comments

@plastikfan
Copy link
Contributor

plastikfan commented Aug 7, 2023

It was discovered that the current design of the worker pool does not work particularly well in the case where cancellation is requested and the lifetime of a job's execution is minutely small, ie the task to be performed is trivial and only takes milliseconds to run. There is also a perplexing characteristic of there being many more worker GRs being active in the pool than the number of CPUs. It was expected that the number of worker GRs would never exceed the number of CPUs, but this almost never occurs.

When a cancellation is received, the supplementary GRs (representing the producer, consumer and worker pool) did act upon the cancellation request in the expected manner. However, the same could not be said about the worker GRs. Since the supplementary GRs' lifetime were long lived, there was enough time for the Go scheduler to run those GRs correctly. But since, with the current design where a worker's GR only lasts for the lifetime of the job, (which for trivial tasks was minute fraction of time) it was difficult if not impossible for the worker GR to receive the cancellation request and therefore have no check against it sending a message to a closed result channel, resulting in a panic. This was confirmed by introducing a delay into the execution path of the worker, which intermittently resulted in a highr number of worker GRs seeing the cancellation request. The problem however, was that it was not very dependable, which probably indicates a race condition (although having said this, using the -race flag never actually resulted in a race condition being reported; but this maybe to be expected as described by "Concurrency In Go" (CiG), specific reference TBD).

Output that shows an example run of the worker-pool with cancellation ...

Worker attempts to write to closed channel

You can add text within a collapsed section.

You can add an image or a code block, too.

 plastikfan@Janus  ~/dev/github/go/snivilised/lorax λ   feat/add-basic-worker-pool ±  task t
[1691343610] Async Suite - 1/3 specs - 7 procs SS
------------------------------
• [0.103 seconds]
WorkerPool producer/consumer when given: cancellation invoked before end of work 🧪 should: close down gracefully
/home/plastikfan/dev/github/go/snivilised/lorax/async/worker-pool_test.go:111

  Captured StdOut/StdErr Output >>
                >>> 💤 Sleeping before requesting stop (200ms) ...
                >>> 💤 Sleeping before requesting cancellation (100ms) ...
  ===> ✨ producer.start ...
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:1 Recipient:johnny 😈}'
  ===> 💠 consumer.start ...
  ---> 🧊 WorkerPool.Run
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (1) dispatch worker: id-'WORKER-ID:f7ac49ef-a3b3-4db5-9bc0-66740e3e82da'
  ---> 🚀 worker.accept: 'WORKER-ID:f7ac49ef-a3b3-4db5-9bc0-66740e3e82da', input:'{1 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:2 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (2) dispatch worker: id-'WORKER-ID:16439381-1daa-417f-afdc-af1905c1df17'
  ---> 🚀 worker.accept: 'WORKER-ID:16439381-1daa-417f-afdc-af1905c1df17', input:'{2 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:3 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (3) dispatch worker: id-'WORKER-ID:61e272f5-6453-403b-9847-a532e0d6ac49'
  ---> 🚀 worker.accept: 'WORKER-ID:61e272f5-6453-403b-9847-a532e0d6ac49', input:'{3 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:4 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (4) dispatch worker: id-'WORKER-ID:17876ad2-3d1c-48ab-8bac-fccc809816a6'
  ---> 🚀 worker.accept: 'WORKER-ID:17876ad2-3d1c-48ab-8bac-fccc809816a6', input:'{4 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:5 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (5) dispatch worker: id-'WORKER-ID:7e2d2f5a-1410-4bd2-b10d-dd2945b41fbd'
  ---> 🚀 worker.accept: 'WORKER-ID:7e2d2f5a-1410-4bd2-b10d-dd2945b41fbd', input:'{5 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:6 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (6) dispatch worker: id-'WORKER-ID:1be9e4ef-3464-449c-836d-93b9ea950672'
  ---> 🚀 worker.accept: 'WORKER-ID:1be9e4ef-3464-449c-836d-93b9ea950672', input:'{6 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:7 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (7) dispatch worker: id-'WORKER-ID:a709ba50-296d-416d-9e2b-b3cb043ecb38'
  ---> 🚀 worker.accept: 'WORKER-ID:a709ba50-296d-416d-9e2b-b3cb043ecb38', input:'{7 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:8 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (8) dispatch worker: id-'WORKER-ID:2563382e-5891-40c3-93d8-3ff7d42d4e06'
  ---> 🚀 worker.accept: 'WORKER-ID:2563382e-5891-40c3-93d8-3ff7d42d4e06', input:'{8 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:9 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (9) dispatch worker: id-'WORKER-ID:3c67ad49-52e3-4385-956b-d119b1df3b02'
  ---> 🚀 worker.accept: 'WORKER-ID:3c67ad49-52e3-4385-956b-d119b1df3b02', input:'{9 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:10 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (10) dispatch worker: id-'WORKER-ID:fe1c2d37-e90a-4713-8f9b-f40b9d167ae3'
  ---> 🚀 worker.accept: 'WORKER-ID:fe1c2d37-e90a-4713-8f9b-f40b9d167ae3', input:'{10 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:11 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (11) dispatch worker: id-'WORKER-ID:3010dc5a-01ab-4e0d-9525-fd17c2f10425'
  ---> 🚀 worker.accept: 'WORKER-ID:3010dc5a-01ab-4e0d-9525-fd17c2f10425', input:'{11 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:12 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (12) dispatch worker: id-'WORKER-ID:984d6373-f0a4-420f-94f1-5baec93aabe9'
  ---> 🚀 worker.accept: 'WORKER-ID:984d6373-f0a4-420f-94f1-5baec93aabe9', input:'{12 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:13 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (13) dispatch worker: id-'WORKER-ID:9a8865b7-10a9-442c-b98e-354282acdbd3'
  ---> 🚀 worker.accept: 'WORKER-ID:9a8865b7-10a9-442c-b98e-354282acdbd3', input:'{13 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:14 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (14) dispatch worker: id-'WORKER-ID:21bbd28f-c61a-40f6-b105-7d1032581034'
  ---> 🚀 worker.accept: 'WORKER-ID:21bbd28f-c61a-40f6-b105-7d1032581034', input:'{14 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:15 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (15) dispatch worker: id-'WORKER-ID:c50c484f-98b0-4720-8f7d-f5c40d86b99f'
  ---> 🚀 worker.accept: 'WORKER-ID:c50c484f-98b0-4720-8f7d-f5c40d86b99f', input:'{15 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:16 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (16) dispatch worker: id-'WORKER-ID:8099fdc9-e071-4832-815c-1580387c7ac3'
  ---> 🚀 worker.accept: 'WORKER-ID:8099fdc9-e071-4832-815c-1580387c7ac3', input:'{16 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:17 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (17) dispatch worker: id-'WORKER-ID:b7fdceea-23ab-475c-86fb-7c414d3f668e'
  ---> 🚀 worker.accept: 'WORKER-ID:b7fdceea-23ab-475c-86fb-7c414d3f668e', input:'{17 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:18 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (18) dispatch worker: id-'WORKER-ID:e8596341-87cf-4630-94fb-7838423c2dfc'
  ---> 🚀 worker.accept: 'WORKER-ID:e8596341-87cf-4630-94fb-7838423c2dfc', input:'{18 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:19 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (19) dispatch worker: id-'WORKER-ID:659683a4-4371-4566-bb9d-e4f85260abd3'
  ---> 🚀 worker.accept: 'WORKER-ID:659683a4-4371-4566-bb9d-e4f85260abd3', input:'{19 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:20 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (20) dispatch worker: id-'WORKER-ID:766da0f7-d664-4648-bf0b-747d6b42a719'
  ---> 🚀 worker.accept: 'WORKER-ID:766da0f7-d664-4648-bf0b-747d6b42a719', input:'{20 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:21 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (21) dispatch worker: id-'WORKER-ID:cda4ebd0-8fdf-4d2c-bb51-09b18b48c4ae'
  ---> 🚀 worker.accept: 'WORKER-ID:cda4ebd0-8fdf-4d2c-bb51-09b18b48c4ae', input:'{21 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:22 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (22) dispatch worker: id-'WORKER-ID:67e8f73b-ba23-46f7-b8b9-f4055323fe13'
  ---> 🚀 worker.accept: 'WORKER-ID:67e8f73b-ba23-46f7-b8b9-f4055323fe13', input:'{22 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:23 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (23) dispatch worker: id-'WORKER-ID:3f260f7a-75d1-403c-a9c9-86eeabf2f939'
  ---> 🚀 worker.accept: 'WORKER-ID:3f260f7a-75d1-403c-a9c9-86eeabf2f939', input:'{23 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:24 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (24) dispatch worker: id-'WORKER-ID:a85e3ddc-f588-44d1-be6e-29b5bb1dbe96'
  ---> 🚀 worker.accept: 'WORKER-ID:a85e3ddc-f588-44d1-be6e-29b5bb1dbe96', input:'{24 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:25 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (25) dispatch worker: id-'WORKER-ID:73dc9bcf-f8c6-43b7-a003-d5f3037d4ee5'
  ---> 🚀 worker.accept: 'WORKER-ID:73dc9bcf-f8c6-43b7-a003-d5f3037d4ee5', input:'{25 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:26 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (26) dispatch worker: id-'WORKER-ID:a950c020-b43d-447b-a20d-de7febbf005a'
  ---> 🚀 worker.accept: 'WORKER-ID:a950c020-b43d-447b-a20d-de7febbf005a', input:'{26 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:27 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (27) dispatch worker: id-'WORKER-ID:d7a66be2-4333-47a3-82ba-894208c648c5'
  ---> 🚀 worker.accept: 'WORKER-ID:d7a66be2-4333-47a3-82ba-894208c648c5', input:'{27 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:28 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (28) dispatch worker: id-'WORKER-ID:c28a70a4-d895-4c76-b3cc-8ed5f94f2964'
  ---> 🚀 worker.accept: 'WORKER-ID:c28a70a4-d895-4c76-b3cc-8ed5f94f2964', input:'{28 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:29 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (29) dispatch worker: id-'WORKER-ID:7d2f0520-0701-4b6c-b5ff-a7f341be2ebc'
  ---> 🚀 worker.accept: 'WORKER-ID:7d2f0520-0701-4b6c-b5ff-a7f341be2ebc', input:'{29 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:30 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (30) dispatch worker: id-'WORKER-ID:d26eb323-84ea-4f81-bd94-f3931fe919ec'
  ---> 🚀 worker.accept: 'WORKER-ID:d26eb323-84ea-4f81-bd94-f3931fe919ec', input:'{30 johnny 😈}'
        ---> exec.Invoke [Seq: 4]🍉 Hello: 'johnny 😈'
  ---> 🧊 WorkerPool.Run - worker(WORKER-ID:17876ad2-3d1c-48ab-8bac-fccc809816a6) finished
  ---> 💠 new result arrived(#1): '{Payload:    ---> exec.Invoke [Seq: 4]🍉 Hello: 'johnny 😈'}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:31 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (30) dispatch worker: id-'WORKER-ID:836883f4-387e-4a6d-a95b-4c98503fc3c7'
  ---> 🚀 worker.accept: 'WORKER-ID:836883f4-387e-4a6d-a95b-4c98503fc3c7', input:'{31 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:32 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (31) dispatch worker: id-'WORKER-ID:86259ca3-a274-4aa5-81ed-3b600ee8b8f9'
  ---> 🚀 worker.accept: 'WORKER-ID:86259ca3-a274-4aa5-81ed-3b600ee8b8f9', input:'{32 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:33 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (32) dispatch worker: id-'WORKER-ID:3d0d6901-97aa-4659-94bc-9545ca7df652'
  ---> 🚀 worker.accept: 'WORKER-ID:3d0d6901-97aa-4659-94bc-9545ca7df652', input:'{33 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:34 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (33) dispatch worker: id-'WORKER-ID:ffc9494e-b866-4f4c-bee4-0537626e12dd'
  ---> 🚀 worker.accept: 'WORKER-ID:ffc9494e-b866-4f4c-bee4-0537626e12dd', input:'{34 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:35 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (34) dispatch worker: id-'WORKER-ID:104feee5-4d71-4d9c-8c8f-ae2dacf5cbb9'
  ---> 🚀 worker.accept: 'WORKER-ID:104feee5-4d71-4d9c-8c8f-ae2dacf5cbb9', input:'{35 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:36 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (35) dispatch worker: id-'WORKER-ID:cb5875e7-723d-40b5-92c0-daeeeacf6e87'
  ---> 🚀 worker.accept: 'WORKER-ID:cb5875e7-723d-40b5-92c0-daeeeacf6e87', input:'{36 johnny 😈}'
        ---> exec.Invoke [Seq: 1]🍉 Hello: 'johnny 😈'
  ---> 🧊 WorkerPool.Run - worker(WORKER-ID:f7ac49ef-a3b3-4db5-9bc0-66740e3e82da) finished
  ---> 💠 new result arrived(#2): '{Payload:    ---> exec.Invoke [Seq: 1]🍉 Hello: 'johnny 😈'}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:37 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (35) dispatch worker: id-'WORKER-ID:e3e5341b-0c75-47a2-8590-cd16661e10f8'
  ---> 🚀 worker.accept: 'WORKER-ID:e3e5341b-0c75-47a2-8590-cd16661e10f8', input:'{37 johnny 😈}'
        ---> exec.Invoke [Seq: 30]🍉 Hello: 'johnny 😈'
  ---> 🧊 WorkerPool.Run - worker(WORKER-ID:d26eb323-84ea-4f81-bd94-f3931fe919ec) finished
  ---> 💠 new result arrived(#3): '{Payload:    ---> exec.Invoke [Seq: 30]🍉 Hello: 'johnny 😈'}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:38 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (35) dispatch worker: id-'WORKER-ID:4834d50a-ff2a-4045-9a39-5d1b89b0bc8b'
  ---> 🚀 worker.accept: 'WORKER-ID:4834d50a-ff2a-4045-9a39-5d1b89b0bc8b', input:'{38 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:39 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (36) dispatch worker: id-'WORKER-ID:a74fbd5a-9476-433b-afe7-0d7874d05d84'
  ---> 🚀 worker.accept: 'WORKER-ID:a74fbd5a-9476-433b-afe7-0d7874d05d84', input:'{39 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:40 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (37) dispatch worker: id-'WORKER-ID:c671e26c-5772-4462-9047-3780b886e41d'
  ---> 🚀 worker.accept: 'WORKER-ID:c671e26c-5772-4462-9047-3780b886e41d', input:'{40 johnny 😈}'
        ---> exec.Invoke [Seq: 5]🍉 Hello: 'johnny 😈'
  ---> 🧊 WorkerPool.Run - worker(WORKER-ID:7e2d2f5a-1410-4bd2-b10d-dd2945b41fbd) finished
  ---> 💠 new result arrived(#4): '{Payload:    ---> exec.Invoke [Seq: 5]🍉 Hello: 'johnny 😈'}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:41 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (37) dispatch worker: id-'WORKER-ID:c3dc602e-1907-4042-8be1-b649526ba6d6'
  ---> 🚀 worker.accept: 'WORKER-ID:c3dc602e-1907-4042-8be1-b649526ba6d6', input:'{41 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:42 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (38) dispatch worker: id-'WORKER-ID:f0fa6322-6549-403b-a3f8-4c6f7872a2dc'
  ---> 🚀 worker.accept: 'WORKER-ID:f0fa6322-6549-403b-a3f8-4c6f7872a2dc', input:'{42 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:43 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (39) dispatch worker: id-'WORKER-ID:90b26893-d90a-4ed2-9b2f-dd52cf4fb8cd'
  ---> 🚀 worker.accept: 'WORKER-ID:90b26893-d90a-4ed2-9b2f-dd52cf4fb8cd', input:'{43 johnny 😈}'
  ---> ✨ producer.start/default(running: true) ...
  ===> ✨ producer.item, posted item: '{sequenceNo:44 Recipient:johnny 😈}'
  ---> 🧊 WorkerPool.Run - new job received
  ---> 🧊 (40) dispatch worker: id-'WORKER-ID:2fe25574-7c3c-41a2-8b79-0802610bed3d'
  ---> 🚀 worker.accept: 'WORKER-ID:2fe25574-7c3c-41a2-8b79-0802610bed3d', input:'{44 johnny 😈}'
  ===> consumer finished (Quit). 💠💠💠
  !!!! 🧊 WorkerPool.drain - waiting for remaining workers: 40 (#GRs: 54); 🧊🧊🧊
  <--- WorkerPool finished (Quit). 🧊🧊🧊
  ===> producer finished (Quit). ✨✨✨
  <--- orpheus(alpha) finished Counts >>> (Producer: '44', Consumer: '4'). 🎯🎯🎯
  << Captured StdOut/StdErr Output
------------------------------
 SUCCESS! 106.4971ms
[1691343610] I18n Suite - 0/0 specs - 7 procs  SUCCESS! 6.2468ms

Ginkgo ran 2 suites in 1.435782789s
Test Suite Passed
Detected Programmatic Focus - setting exit status to 197
task: Failed to run task "t": exit status 197
 ✘ plastikfan@Janus  ~/dev/github/go/snivilised/lorax λ   feat/add-basic-worker-pool ±  task t
[1691343676] Async Suite - 1/3 specs - 7 procs SS
Ginkgo timed out waiting for all parallel procs to report back
Test suite: async (./async)

This occurs if a parallel process exits before it reports its results to the
Ginkgo CLI.  The CLI will now print out all the stdout/stderr output it's
collected from the running processes.  However you may not see anything useful
in these logs because the individual test processes usually intercept output to
stdout/stderr in order to capture it in the spec reports.

You may want to try rerunning your test suite with
--output-interceptor-mode=none to see additional output here and debug your
suite.

Output from proc 1:
  PASS | FOCUSED

Output from proc 2:
        ---> exec.Invoke [Seq: 25]🍉 Hello: 'johnny 😈'
  panic: send on closed channel

  goroutine 48 [running]:
  github.com/snivilised/lorax/async.(*worker[...]).accept(0xc0000aa360, {0x8c71b8, 0xc0001bf240}, 0xc0000a28d0)
        /home/plastikfan/dev/github/go/snivilised/lorax/async/worker.go:23 +0x1b7
  created by github.com/snivilised/lorax/async.(*WorkerPool[...]).dispatch
        /home/plastikfan/dev/github/go/snivilised/lorax/async/worker-pool.go:240 +0x24e

Output from proc 3:
  PASS | FOCUSED

Output from proc 4:
  PASS | FOCUSED

Output from proc 5:
  PASS | FOCUSED

Output from proc 6:
  PASS | FOCUSED

Output from proc 7:
  PASS | FOCUSED

** End **
Ginkgo ran 2 suites in 1.929093417s

There were failures detected in the following suites:
  async ./async

Test Suite Failed
task: Failed to run task "t": exit status 1

The new design should adhere to the fact that the pool should only spin up workers as when work arrives. It should not spin up everything regardless of the workload as that would be inefficient.

  • the parent child relationship between the pool and the workers as documented on page 91 CiG, in order to prevent GR leakage. So the source cancellation is handled by the pool which delegates to the workers. ❗Remember, GRs are not garbage collected which gives rise to a possible explanation of the larger than expected number of GRs in the current design of the pool at the end of the processing batch.

  • in the worker pool, create another struct (possibly embedded) that contains any state that is non synchronised and is for the sole use of the worker-pool thread. This way, we can have a clear separation between state that should be consider private to the worker pool GR and therefore shouldn't need to be synchronised, and state that can be accessed by methods that can also ne accessed by other GRs and therefore should be synchronised. This will help to show clear intent in the code as to which GRs can call specific methods.

  • go routine leakage can be checked for using uber's goleak, also see Detecting Goroutine Leaks with Test Cases

@plastikfan plastikfan self-assigned this Aug 7, 2023
@plastikfan plastikfan added the feature New feature or request label Aug 7, 2023
@plastikfan
Copy link
Contributor Author

plastikfan commented Aug 10, 2023

Some temp test code ...

  • worker-pool_test.go
		When("given: a stream of jobs", func() {
			It("🧪 should: receive and process all", func(specCtx SpecContext) {
				var (
					wg sync.WaitGroup
				)
				sequence := 0
				resultsCh := make(chan async.JobResult[TestJobResult], ResultChSize)

				By("👾 WAIT-GROUP ADD(producer)")
				wg.Add(1)
				provider := func() TestJobInput {
					sequence++
					return TestJobInput{
						sequenceNo: sequence,
						Recipient:  "jimmy 🦊",
					}
				}
				producer := helpers.NewProducer[TestJobInput, TestJobResult](
					specCtx, &wg, JobChSize, provider, Delay,
				)

				pool := async.NewWorkerPool[TestJobInput, TestJobResult](
					&async.NewWorkerPoolParams[TestJobInput, TestJobResult]{
						Exec:   &exec{},
						JobsCh: producer.JobsCh,
						Cancel: make(async.CancelStream),
						Quit:   &wg,
					})

				By("👾 WAIT-GROUP ADD(worker-pool)\n")
				wg.Add(1)
				go pool.Run(specCtx, resultsCh)

				By("👾 WAIT-GROUP ADD(consumer)")
				wg.Add(1)
				consumer := helpers.NewConsumer(specCtx, &wg, resultsCh)

				go func() {
					snooze := time.Second / 5
					fmt.Printf("		>>> 💤 Sleeping before requesting stop (%v) ...\n", snooze)
					time.Sleep(snooze)
					producer.Stop()
					fmt.Printf("		>>> 🍧🍧🍧 stop submitted.\n")
				}()

				wg.Wait()
				fmt.Printf("<--- orpheus(alpha) finished Counts >>> (Producer: '%v', Consumer: '%v'). 🎯🎯🎯\n",
					producer.Count,
					consumer.Count,
				)

				Expect(producer.Count).To(Equal(consumer.Count))
				Eventually(specCtx, resultsCh).WithTimeout(time.Second * 2).Should(BeClosed())
				Eventually(specCtx, producer.JobsCh).WithTimeout(time.Second * 2).Should(BeClosed())
			}, SpecTimeout(time.Second*2))
		})

		When("given: cancellation invoked before end of work", func() {
			XIt("🧪 should: close down gracefully", func(specCtx SpecContext) {
				// this case shows that worker pool needs a redesign. Each worker
				// go routine needs to have a lifetime that spans the lifetime of
				// the session, rather than a short lifetime that matches that of
				// an individual job. This will make processing more reliable,
				// especially when it comes to cancellation. As it is, since the
				// worker GR only exists for the lifetime of the job, when the
				// job is short (in duration), it is very unlikely it will see
				// the cancellation request and therefore and therefore likely
				// to send to a closed channel (the result channel).
				//
				var (
					wg sync.WaitGroup
				)
				sequence := 0
				resultsCh := make(chan async.JobResult[TestJobResult], ResultChSize)

				By("👾 WAIT-GROUP ADD(producer)")
				wg.Add(1)
				provider := func() TestJobInput {
					sequence++
					return TestJobInput{
						sequenceNo: sequence,
						Recipient:  "johnny 😈",
					}
				}
				ctx, cancel := context.WithCancel(specCtx)

				producer := helpers.NewProducer[TestJobInput, TestJobResult](ctx, &wg, JobChSize, provider, Delay)
				pool := async.NewWorkerPool[TestJobInput, TestJobResult](&async.NewWorkerPoolParams[TestJobInput, TestJobResult]{
					Exec:   &exec{},
					JobsCh: producer.JobsCh,
					Cancel: make(async.CancelStream),
					Quit:   &wg,
				})

				By("👾 WAIT-GROUP ADD(worker-pool)\n")
				wg.Add(1)
				go pool.Run(ctx, resultsCh)

				By("👾 WAIT-GROUP ADD(consumer)")
				wg.Add(1)
				consumer := helpers.NewConsumer(ctx, &wg, resultsCh)

				go func() {
					snooze := time.Second / 10
					fmt.Printf("		>>> 💤 Sleeping before requesting cancellation (%v) ...\n", snooze)
					time.Sleep(snooze)
					cancel()
					fmt.Printf("		>>> 🍧🍧🍧 cancel submitted.\n")
				}()

				wg.Wait()
				fmt.Printf("<--- orpheus(alpha) finished Counts >>> (Producer: '%v', Consumer: '%v'). 🎯🎯🎯\n",
					producer.Count,
					consumer.Count,
				)

				Eventually(specCtx, resultsCh).WithTimeout(time.Second * 2).Should(BeClosed())
				Eventually(specCtx, producer.JobsCh).WithTimeout(time.Second * 2).Should(BeClosed())
			}, SpecTimeout(time.Second*2))
		})

	Context("ginkgo consumer", func() {
		It("🧪 should: receive and process all", func(specCtx SpecContext) {
			var (
				wg sync.WaitGroup
			)
			sequence := 0

			resultsCh := make(chan async.JobResult[TestJobResult], ResultChSize)

			By("👾 WAIT-GROUP ADD(producer)")
			wg.Add(1)
			provider := func() TestJobInput {
				sequence++
				return TestJobInput{
					sequenceNo: sequence,
					Recipient:  "cosmo 👽",
				}
			}
			producer := helpers.NewProducer[TestJobInput, TestJobResult](specCtx, &wg, JobChSize, provider, Delay)
			pool := async.NewWorkerPool[TestJobInput, TestJobResult](&async.NewWorkerPoolParams[TestJobInput, TestJobResult]{
				Exec:   &exec{},
				JobsCh: producer.JobsCh,
				Cancel: make(async.CancelStream),
				Quit:   &wg,
			})

			By("👾 WAIT-GROUP ADD(worker-pool)\n")
			wg.Add(1)
			go pool.Run(specCtx, resultsCh)

			By("👾 WAIT-GROUP ADD(consumer)")
			wg.Add(1)
			consumer := helpers.NewConsumer(specCtx, &wg, resultsCh)

			go func() {
				snooze := time.Second / 5
				fmt.Printf("		>>> 💤 Sleeping before requesting stop (%v) ...\n", snooze)
				time.Sleep(snooze)
				producer.Stop()
				fmt.Printf("		>>> 🍧🍧🍧 stop submitted.\n")
			}()

			wg.Wait()
			fmt.Printf("<--- orpheus(alpha) finished Counts >>> (Producer: '%v', Consumer: '%v'). 🎯🎯🎯\n",
				producer.Count,
				consumer.Count,
			)

			Expect(producer.Count).To(Equal(consumer.Count))
			Eventually(specCtx, resultsCh).WithTimeout(time.Second * 2).Should(BeClosed())
			Eventually(specCtx, producer.JobsCh).WithTimeout(time.Second * 2).Should(BeClosed())
		}, SpecTimeout(time.Second*2))
	})

@plastikfan
Copy link
Contributor Author

plastikfan commented Aug 10, 2023

Some temp source code

  • worker-pool.go
// Run
func (p *WorkerPool[I, R]) Run(ctx context.Context, resultsOut ResultStreamOut[R]) {
	defer func() {
		fmt.Printf("<--- WorkerPool finished (Quit). 🧊🧊🧊\n")
		p.Quit.Done()
		close(resultsOut)
	}()
	fmt.Printf("---> 🧊 WorkerPool.Run (with %v workers)\n", p.noWorkers)

	for running := true; running; {
		select {
		case <-ctx.Done():
			fmt.Println("---> 🧊 WorkerPool.Run - done received ☢️☢️☢️")

			running = false

		case job, ok := <-p.JobsCh:
			if ok {
				fmt.Println("---> 🧊 WorkerPool.Run - new job received")

				p.dispatch(ctx, &workerInfo[I, R]{
					job:          job,
					resultsOutCh: resultsOut,
					finishedOut:  p.finishedCh,
				})
			} else {
				running = false
			}

		case workerID := <-p.finishedCh:
			fmt.Printf("---> 🧊 WorkerPool.Run - worker(%v) finished\n", workerID)
			delete(p.private.pool, workerID)
		}
	}

	// we still need to wait for all workers to finish ...
	//
	p.drain(ctx)
}

func (p *WorkerPool[I, R]) dispatch(ctx context.Context, info *workerInfo[I, R]) {
	w := &workerWrapper[I, R]{
		core: &worker[I, R]{
			id: p.composeID(),
			fn: p.fn,
		},
	}

	p.private.pool[w.core.id] = w
	fmt.Printf("---> 🧊 (pool-size: %v) dispatch worker: id-'%v'\n", len(p.private.pool), w.core.id)

	go w.core.accept(ctx, info) // BREAKS: when cancellation occurs, send on closed chan
}
  • worker.go
func (w *worker[I, R]) accept(ctx context.Context, info *workerInfo[I, R]) {
	fmt.Printf("---> 🚀 worker.accept: '%v', input:'%v'\n", w.id, info.job.Input)
	result, _ := w.fn.Invoke(info.job)

	select { // BREAKS: when cancellation occurs, send on closed chan
	case <-ctx.Done():
		fmt.Println("---> 🚀 worker.accept(result) - done received 💥💥💥")

	case info.resultsOutCh <- result:
	}

	select {
	case <-ctx.Done():
		fmt.Println("---> 🚀 worker.accept(finished) - done received ❌❌❌")

	case info.finishedOut <- w.id:
	}
}

@plastikfan
Copy link
Contributor Author

Some speculative join channels code:

  • join-channels.go
func JoinChannels[T any](ctx context.Context, inCh <-chan T, outCh chan<- T, fn JoinChannelsFunc[T]) {
	fn(inCh, outCh)
	select {
	case <-ctx.Done():
		fmt.Println("---> 💎 JoinChannels(in) - done received")
	case item := <-inCh:
		select {
		case <-ctx.Done():
			fmt.Println("---> 💎 JoinChannels(out) - done received")
		case outCh <- item:
		}
	}
}

@plastikfan
Copy link
Contributor Author

plastikfan commented Aug 11, 2023

An important discovery has been made whilst working on this issue. Care must be taken when using ctx.Done() channel. Must make sure that it is not abused, once a ctx.Done() has fired, the channel is closed so don't try and reuse in subsequent select statements. This is because subsequent select statements that use this channel will short-circuit and the other cases in the select will not get a chance to be selected.

Although this did fix a problem of the drain functionality working, it still hasn't exposed the still remaining problem of the wait() being indefinitely blocked, resulting in the test spec timing out. The current state of the test case run is as indicated below:

Output that shows an example run of the spec timing out, blocking on the final wait ...
 plastikfan@Janus  ~/dev/github/go/snivilised/lorax λ   feat/change-worker-lifetime ±  task t
[1691743960] Async Suite - 1/2 specs - 7 procs S
------------------------------
• [TIMEDOUT] [5.001 seconds]
WorkerPool when given: a stream of jobs and: Stopped [It] 🧪 should: receive and process all
/home/plastikfan/dev/github/go/snivilised/lorax/async/worker-pool_test.go:144

  Captured StdOut/StdErr Output >>
                >>> 💤 Sleeping before requesting stop (200ms) ...
  >>>> ✨ producer.run ...
  ===> 🧊 WorkerPool.run
  <<<< 💠 consumer.run ...
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:1 Recipient:👽 paul}'
  ===> 🧊 (#workers: '0') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:f6e6212e-a7a2-43e6-8e92-b3869850dbb7)
        ---> 🚀 worker.run((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5)(input:'{1 👽 paul}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:2 Recipient:👻 caspar}'
  ===> 🧊 (#workers: '1') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:c2018a2c-be25-422e-923c-24db6e48c015)
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{2 👻 caspar}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:3 Recipient:👺 gobby}'
  ===> 🧊 (#workers: '2') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:505802eb-14db-4c9c-8391-be96ccccf1bb)
        ---> 🚀 worker.run((💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb)(input:'{3 👺 gobby}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:4 Recipient:👹 ogre}'
  ===> 🧊 (#workers: '3') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:604bd445-b148-4ecc-ae37-c0f5b4c526a6)
        ---> 🚀 worker.run((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817)(input:'{4 👹 ogre}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:5 Recipient:👺 gobby}'
  ===> 🧊 (#workers: '4') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:3b30bd22-b23b-4a93-8885-2380f41569ef)
        ---> 🚀 worker.run((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629)(input:'{5 👺 gobby}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:6 Recipient:👺 gobby}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:61650799-e5a3-422a-9787-593d492c058e)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:7 Recipient:👺 gobby}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:4720fe44-ec35-4cf8-94fa-48b7f6a10726)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:8 Recipient:👾 xenomorph}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:ff3fa884-f5ed-4944-8af5-1621a2377d59)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:9 Recipient:👻 caspar}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:5de031bf-1c2e-43c3-ba39-f5a0b3628182)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:10 Recipient:💩 poo}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:0a9f76fb-36c8-4955-8511-427e05b7fbcc)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:11 Recipient:🧛‍♀️ vampire}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:12 Recipient:💩 poo}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:13 Recipient:👿 nick}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:14 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:15 Recipient:🐉 smaug}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:16 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:17 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:18 Recipient:🐉 smaug}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:19 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:20 Recipient:👻 caspar}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:21 Recipient:💩 poo}'
  >>>> ✨ producer.run - default (running: true) ...
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{6 👺 gobby}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:ced2a6a9-9617-4f6a-88c5-b4e73277759f)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  >>>> ✨ producer.item, posted item: '{sequenceNo:22 Recipient:👹 ogre}'
  <<<< 💠 consumer.run - new result arrived(#1): '                      ---> 🍉🍉🍉 [Seq: 2] Hello: '👻 caspar''
  >>>> ✨ producer.run - default (running: true) ...
        ---> 🚀 worker.run((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817)(input:'{7 👺 gobby}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:3028db44-405d-4bde-b5fb-850faf192879)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  >>>> ✨ producer.item, posted item: '{sequenceNo:23 Recipient:😺 garfield}'
  <<<< 💠 consumer.run - new result arrived(#2): '                      ---> 🍉🍉🍉 [Seq: 4] Hello: '👹 ogre''
  >>>> ✨ producer.run - default (running: true) ...
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{8 👾 xenomorph}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:166f85be-3575-45a5-bf74-910468574941)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  >>>> ✨ producer.item, posted item: '{sequenceNo:24 Recipient:🦄 pegasus}'
  <<<< 💠 consumer.run - new result arrived(#3): '                      ---> 🍉🍉🍉 [Seq: 6] Hello: '👺 gobby''
  >>>> ✨ producer.run - default (running: true) ...
  >>>> 🧲 producer terminating ...
        ---> 🚀 worker.run((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629)(input:'{9 👻 caspar}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:e21b3ba8-bb4c-41ae-951a-807d23666e50)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  >>>> ✨ producer.item, posted item: '{sequenceNo:25 Recipient:👻 caspar}'
  >>>> ✨ producer.run - termination detected (running: false)
  >>>> producer.run - finished (QUIT). ✨✨✨
                >>> 🍧🍧🍧 stop submitted.
  <<<< 💠 consumer.run - new result arrived(#4): '                      ---> 🍉🍉🍉 [Seq: 5] Hello: '👺 gobby''
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{10 💩 poo}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:6bd915e5-5773-4889-b352-ad8dfbb0bfee)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#5): '                      ---> 🍉🍉🍉 [Seq: 8] Hello: '👾 xenomorph''
        ---> 🚀 worker.run((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817)(input:'{11 🧛‍♀️ vampire}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:4b5dc066-d95b-48e0-b1ee-cde9e576f3b0)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#6): '                      ---> 🍉🍉🍉 [Seq: 7] Hello: '👺 gobby''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5)(input:'{12 💩 poo}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:eab59bae-fd43-438e-9496-28f89fa2ef64)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#7): '                      ---> 🍉🍉🍉 [Seq: 1] Hello: '👽 paul''
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{13 👿 nick}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:03eac6be-9d2a-4ddb-9345-09bb2d744d26)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#8): '                      ---> 🍉🍉🍉 [Seq: 10] Hello: '💩 poo''
        ---> 🚀 worker.run((💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb)(input:'{14 👾 xenomorph}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:a79282da-595e-4ebf-a5ad-bacc266d6bd6)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#9): '                      ---> 🍉🍉🍉 [Seq: 3] Hello: '👺 gobby''
        ---> 🚀 worker.run((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817)(input:'{15 🐉 smaug}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:94f928fe-c389-435e-a321-c3ca2d215c56)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#10): '                     ---> 🍉🍉🍉 [Seq: 11] Hello: '🧛‍♀️ vampire''
        ---> 🚀 worker.run((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629)(input:'{16 👾 xenomorph}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:01b900e2-b29f-48f0-8469-ac355306e357)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#11): '                     ---> 🍉🍉🍉 [Seq: 9] Hello: '👻 caspar''
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{17 👾 xenomorph}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:36cdd93e-d214-4004-85b2-9e0e09470c06)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#12): '                     ---> 🍉🍉🍉 [Seq: 13] Hello: '👿 nick''
        ---> 🚀 worker.run((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817)(input:'{18 🐉 smaug}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:6cca5dd7-060a-4d6f-a80a-3f078bb30890)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#13): '                     ---> 🍉🍉🍉 [Seq: 15] Hello: '🐉 smaug''
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{19 👾 xenomorph}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:0b55103a-0b39-4c64-a165-bb08d2ac7da4)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#14): '                     ---> 🍉🍉🍉 [Seq: 17] Hello: '👾 xenomorph''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5)(input:'{20 👻 caspar}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:5d1f666d-154c-49bb-82c9-c16ed96b1e0c)
  ===> 🚀 WorkerPool.run(jobs chan closed) 🟥🟥🟥
  !!!! 🧊 WorkerPool.drain - waiting for remaining workers: 5 (#GRs: 18); 🧊🧊🧊
  <<<< 💠 consumer.run - new result arrived(#15): '                     ---> 🍉🍉🍉 [Seq: 12] Hello: '💩 poo''
        ---> 🚀 worker.run((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629)(input:'{21 💩 poo}')
  <<<< 💠 consumer.run - new result arrived(#16): '                     ---> 🍉🍉🍉 [Seq: 16] Hello: '👾 xenomorph''
        ---> 🚀 worker.run((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629)(input:'{22 👹 ogre}')
  <<<< 💠 consumer.run - new result arrived(#17): '                     ---> 🍉🍉🍉 [Seq: 21] Hello: '💩 poo''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5)(input:'{23 😺 garfield}')
  <<<< 💠 consumer.run - new result arrived(#18): '                     ---> 🍉🍉🍉 [Seq: 20] Hello: '👻 caspar''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5)(input:'{24 🦄 pegasus}')
  <<<< 💠 consumer.run - new result arrived(#19): '                     ---> 🍉🍉🍉 [Seq: 23] Hello: '😺 garfield''
        ---> 🚀 worker.run((💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb)(input:'{25 👻 caspar}')
  <<<< 💠 consumer.run - new result arrived(#20): '                     ---> 🍉🍉🍉 [Seq: 14] Hello: '👾 xenomorph''
  <<<< 💠 consumer.run - new result arrived(#21): '                     ---> 🍉🍉🍉 [Seq: 22] Hello: '👹 ogre''
  <<<< 💠 consumer.run - new result arrived(#22): '                     ---> 🍉🍉🍉 [Seq: 24] Hello: '🦄 pegasus''
  <<<< 💠 consumer.run - new result arrived(#23): '                     ---> 🍉🍉🍉 [Seq: 18] Hello: '🐉 smaug''
  <<<< 💠 consumer.run - new result arrived(#24): '                     ---> 🍉🍉🍉 [Seq: 19] Hello: '👾 xenomorph''
  <<<< 💠 consumer.run - new result arrived(#25): '                     ---> 🍉🍉🍉 [Seq: 25] Hello: '👻 caspar''
        ---> 🚀 worker.run((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629)(finished) - done received 🔶🔶🔶
        <--- 🚀 worker.run((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💛)WORKER-ID-5:c6387849-db48-4ded-a440-34b443014629) finished, remaining: '4' 🟥
        ---> 🚀 worker.run((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817)(finished) - done received 🔶🔶🔶
        <--- 🚀 worker.run((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💜)WORKER-ID-4:a075d0be-9413-4e7e-8a55-4da68a851817) finished, remaining: '3' 🟥
        ---> 🚀 worker.run((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5)(finished) - done received 🔶🔶🔶
        <--- 🚀 worker.run((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((❤️)WORKER-ID-1:b5b1895c-2d31-4d00-9e83-ecb3417333a5) finished, remaining: '2' 🟥
  <<<< 💠 consumer.run - done received 💔💔💔
  <<<< consumer.run - finished (QUIT). 💠💠💠
        ---> 🚀 worker.run((💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb)(finished) - done received 🔶🔶🔶
        <--- 🚀 worker.run((💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb) finished, remaining: '1' 🟥
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(finished) - done received 🔶🔶🔶
        <--- 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05) finished, remaining: '0' 🟥
  ===> 🧊 WorkerPool.run - drain complete (workers count: '0'). 🎃🎃🎃
  <--- WorkerPool.run (QUIT). 🧊🧊🧊
  <--- orpheus(alpha) finished Counts >>> (Producer: '25', Consumer: '25'). 🎯🎯🎯
  << Captured StdOut/StdErr Output

  Timeline >>
  STEP: 👾 WAIT-GROUP ADD(producer) @ 08/11/23 09:52:41.252
  STEP: 👾 WAIT-GROUP ADD(worker-pool)
   @ 08/11/23 09:52:41.252
  STEP: 👾 WAIT-GROUP ADD(consumer) @ 08/11/23 09:52:41.252
  STEP: 👾 NOW AWAITING TERMINATION @ 08/11/23 09:52:41.252
  [TIMEDOUT] in [It] - /home/plastikfan/dev/github/go/snivilised/lorax/async/worker-pool_test.go:144 @ 08/11/23 09:52:46.252
  << Timeline

@plastikfan
Copy link
Contributor Author

plastikfan commented Aug 11, 2023

What the above spec output shows us is:

  • There a five workers. We can see the pool grows in size to meet demand as the jobs are received:
  ===> 🧊 (#workers: '2') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💚)WORKER-ID-3:f2209f39-c182-4a74-acf9-a137283de7cb' 🎀🎀🎀
  • During the growth phase, the pool spawns new workers
  • As jobs are received, the pool forwards the jobs onto the worker job queue and the worker reads from that queue and runs the job:
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:c2018a2c-be25-422e-923c-24db6e48c015)
        ---> 🚀 worker.run((💙)WORKER-ID-2:926adcb2-edfb-425b-b60f-bef42bad6f05)(input:'{2 👻 caspar}')
  • The job queue is larger than the worker capacity, so the queue extends (size of the buffered job channel is set to 10):
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:12 Recipient:💩 poo}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:13 Recipient:👿 nick}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:14 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:15 Recipient:🐉 smaug}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:16 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:17 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:18 Recipient:🐉 smaug}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:19 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:20 Recipient:👻 caspar}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:21 Recipient:💩 poo}'
  >>>> ✨ producer.run - default (running: true) ...

after the capacity of 10 is reached, it looks like the producer starts to block until workers have a chance to consume the jobs (This indeed has been confirmed in another run (not illustrated here), by extending the job size, we see that this burst is extended to match the capacity of the buffer).

  • As the workers run the jobs, they send their results to the results channel which are received by the consumer:
  <<<< 💠 consumer.run - new result arrived(#1): '                      ---> 🍉🍉🍉 [Seq: 2] Hello: '👻 caspar''

... and this also shows us that the results are not guaranteed to be received in order, note the #Count vs the sequence number. Depending the requirements of the client application, this ordering may or may not be significant. In future update, we'll add a feature that guarantees the correct sequencing probably using a reactive model.

  • The test case is defined with a request to stop the producer after a fixed amount of time:
>>>> 🧲 producer terminating ...

... when this time elapses, we see the producer closes the job channel to indicate the end of the workload:

  >>>> producer.run - finished (QUIT). ✨✨✨
                >>> 🍧🍧🍧 stop submitted.

The pool and workers continue to process the remaining workload until the closure of the job channel is detected:

 ===> 🚀 WorkerPool.run(jobs chan closed) 🟥🟥🟥

The pool needs to wait for the remaining workers to complete their work. They will continue whilst there are still outstanding jobs in the worker job queue. The pool exits its run loop and enters the drain phase:

!!!! 🧊 WorkerPool.drain - waiting for remaining workers: 5 (#GRs: 18); 🧊🧊🧊

This is how the pool waits for the remaining workers.

  • workers continue their run loops until the jobs queue is exhausted. When the closure of the jobs

@plastikfan
Copy link
Contributor Author

plastikfan commented Aug 11, 2023

Bingo, I found the problem: when the source job queue closure is detected, we then need to close the workers job queue. This fixed the wait deadlock!

So a successful run looks like this:

Output that shows an example run of the worker-pool with cancellation ...
                >>> 💤 Sleeping before requesting stop (200ms) ...
  >>>> ✨ producer.run ...
  ===> 🧊 WorkerPool.run
  <<<< 💠 consumer.run ...
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:1 Recipient:👾 xenomorph}'
  ===> 🧊 (#workers: '0') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:29d2c7b7-2bff-48c8-81f8-94e9be81a2b5)
        ---> 🚀 worker.run((❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2)(input:'{1 👾 xenomorph}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:2 Recipient:💩 poo}'
  ===> 🧊 (#workers: '1') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:8070b0d9-bc00-404c-9fe4-0f93cf35ebe3)
        ---> 🚀 worker.run((💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86)(input:'{2 💩 poo}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:3 Recipient:🦄 pegasus}'
  ===> 🧊 (#workers: '2') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:fa6dff3b-5712-4a67-9fe4-14e7cb6a94f2)
        ---> 🚀 worker.run((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9)(input:'{3 🦄 pegasus}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:4 Recipient:👺 gobby}'
  ===> 🧊 (#workers: '3') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:3d342c6d-8c33-494e-b648-422515c844f3)
        ---> 🚀 worker.run((💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa)(input:'{4 👺 gobby}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:5 Recipient:👻 caspar}'
  ===> 🧊 (#workers: '4') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.spawned new worker: '(💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b' 🎀🎀🎀
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:579cf9e1-15ef-4af3-8a2c-7571da50b374)
        ---> 🚀 worker.run((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b)(input:'{5 👻 caspar}')
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:6 Recipient:🦄 pegasus}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:278e460f-b87d-434e-9037-0181012cc0c8)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:7 Recipient:👻 caspar}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:8f5feffe-0494-462e-94a0-4734b1c2f337)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:8 Recipient:💀 skeletor}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:0200c610-f625-45f4-b144-0642513b22aa)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:9 Recipient:💀 skeletor}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:e2c9e5c3-7f19-4260-bbdc-4667c4757cc9)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:10 Recipient:👿 nick}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:60859f2e-afdf-4e2c-ba47-ab1cdb8d0ba8)
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:11 Recipient:💀 skeletor}'
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:12 Recipient:🐉 smaug}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:13 Recipient:🧙 gandalf}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:14 Recipient:💀 skeletor}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:15 Recipient:💀 skeletor}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:16 Recipient:👺 gobby}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:17 Recipient:👻 caspar}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:18 Recipient:👾 xenomorph}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:19 Recipient:🦄 pegasus}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:20 Recipient:🤖 rusty}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> ✨ producer.item, posted item: '{sequenceNo:21 Recipient:💩 poo}'
  >>>> ✨ producer.run - default (running: true) ...
  >>>> 🧲 producer terminating ...
        ---> 🚀 worker.run((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b)(input:'{6 🦄 pegasus}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:69027bd5-eb69-41bd-9cfb-feb5c3f74c51)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  >>>> ✨ producer.item, posted item: '{sequenceNo:22 Recipient:💀 skeletor}'
  >>>> ✨ producer.run - termination detected (running: false)
  >>>> producer.run - finished (QUIT). ✨✨✨
                >>> 🍧🍧🍧 stop submitted.
  <<<< 💠 consumer.run - new result arrived(#1): '                      ---> 🍉🍉🍉 [Seq: 5] Hello: '👻 caspar''
        ---> 🚀 worker.run((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9)(input:'{7 👻 caspar}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:83736d6a-19a1-4c1f-975b-2e73de5601f0)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#2): '                      ---> 🍉🍉🍉 [Seq: 3] Hello: '🦄 pegasus''
        ---> 🚀 worker.run((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b)(input:'{8 💀 skeletor}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:34778964-0832-4323-a038-ebe93f4f1a14)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#3): '                      ---> 🍉🍉🍉 [Seq: 6] Hello: '🦄 pegasus''
        ---> 🚀 worker.run((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b)(input:'{9 💀 skeletor}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:852645c8-c21c-4f43-ad4e-9fd036bf9163)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#4): '                      ---> 🍉🍉🍉 [Seq: 8] Hello: '💀 skeletor''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2)(input:'{10 👿 nick}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:03d4fb7f-9a4f-467c-8aa9-013a7632860b)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#5): '                      ---> 🍉🍉🍉 [Seq: 1] Hello: '👾 xenomorph''
        ---> 🚀 worker.run((💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa)(input:'{11 💀 skeletor}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:17c7163a-75da-42e1-9d6b-430398aa1f62)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#6): '                      ---> 🍉🍉🍉 [Seq: 4] Hello: '👺 gobby''
        ---> 🚀 worker.run((💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86)(input:'{12 🐉 smaug}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:c791f1a4-9db9-4de9-87cd-471eb4c7f61b)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#7): '                      ---> 🍉🍉🍉 [Seq: 2] Hello: '💩 poo''
        ---> 🚀 worker.run((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9)(input:'{13 🧙 gandalf}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:1f3f9ee8-8710-45d2-ae00-216e1b1b51f8)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#8): '                      ---> 🍉🍉🍉 [Seq: 7] Hello: '👻 caspar''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2)(input:'{14 💀 skeletor}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:9a29dfc0-8225-4c42-9553-efe4a8f1eaea)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#9): '                      ---> 🍉🍉🍉 [Seq: 10] Hello: '👿 nick''
        ---> 🚀 worker.run((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9)(input:'{15 💀 skeletor}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:2da26cdd-5e52-4da1-9e3d-d5235a987047)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#10): '                     ---> 🍉🍉🍉 [Seq: 13] Hello: '🧙 gandalf''
        ---> 🚀 worker.run((💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa)(input:'{16 👺 gobby}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:b5c9afaf-6771-40d8-b68b-576167980f7c)
  ===> 🧊 (#workers: '5') WorkerPool.run - new job received
  <<<< 💠 consumer.run - new result arrived(#11): '                     ---> 🍉🍉🍉 [Seq: 11] Hello: '💀 skeletor''
        ---> 🚀 worker.run((💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86)(input:'{17 👻 caspar}')
  ===> 🧊 WorkerPool.run - forwarded job 🧿🧿🧿(JOB-ID:dc548bfd-5660-4e6a-86b5-348f85a6b408)
  ===> 🚀 WorkerPool.run(source jobs chan closed) 🟥🟥🟥
  !!!! 🧊 WorkerPool.drain - waiting for remaining workers: 5 (#GRs: 18); 🧊🧊🧊
  <<<< 💠 consumer.run - new result arrived(#12): '                     ---> 🍉🍉🍉 [Seq: 12] Hello: '🐉 smaug''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2)(input:'{18 👾 xenomorph}')
  <<<< 💠 consumer.run - new result arrived(#13): '                     ---> 🍉🍉🍉 [Seq: 14] Hello: '💀 skeletor''
        ---> 🚀 worker.run((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b)(input:'{19 🦄 pegasus}')
  <<<< 💠 consumer.run - new result arrived(#14): '                     ---> 🍉🍉🍉 [Seq: 9] Hello: '💀 skeletor''
        ---> 🚀 worker.run((💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa)(input:'{20 🤖 rusty}')
  <<<< 💠 consumer.run - new result arrived(#15): '                     ---> 🍉🍉🍉 [Seq: 16] Hello: '👺 gobby''
        ---> 🚀 worker.run((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9)(input:'{21 💩 poo}')
  <<<< 💠 consumer.run - new result arrived(#16): '                     ---> 🍉🍉🍉 [Seq: 15] Hello: '💀 skeletor''
        ---> 🚀 worker.run((💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86)(input:'{22 💀 skeletor}')
  <<<< 💠 consumer.run - new result arrived(#17): '                     ---> 🍉🍉🍉 [Seq: 17] Hello: '👻 caspar''
        ---> 🚀 worker.run((💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86)(jobs chan closed) 🟥🟥🟥
        <--- 🚀 worker.run((💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💙)WORKER-ID-2:48339974-910f-453e-85a6-b7e6aace2d86) finished, remaining: '4' 🟥
  <<<< 💠 consumer.run - new result arrived(#18): '                     ---> 🍉🍉🍉 [Seq: 22] Hello: '💀 skeletor''
        ---> 🚀 worker.run((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b)(jobs chan closed) 🟥🟥🟥
        <--- 🚀 worker.run((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💛)WORKER-ID-5:a4103689-4416-417b-a501-13ba3b6bd51b) finished, remaining: '3' 🟥
  <<<< 💠 consumer.run - new result arrived(#19): '                     ---> 🍉🍉🍉 [Seq: 19] Hello: '🦄 pegasus''
        ---> 🚀 worker.run((❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2)(jobs chan closed) 🟥🟥🟥
        <--- 🚀 worker.run((❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((❤️)WORKER-ID-1:acbb0bf3-9b0d-45af-8e05-d0eda6ad4ac2) finished, remaining: '2' 🟥
  <<<< 💠 consumer.run - new result arrived(#20): '                     ---> 🍉🍉🍉 [Seq: 18] Hello: '👾 xenomorph''
        ---> 🚀 worker.run((💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa)(jobs chan closed) 🟥🟥🟥
        <--- 🚀 worker.run((💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💜)WORKER-ID-4:e89a48de-efcf-441a-b930-20c758ec67aa) finished, remaining: '1' 🟥
  <<<< 💠 consumer.run - new result arrived(#21): '                     ---> 🍉🍉🍉 [Seq: 20] Hello: '🤖 rusty''
        ---> 🚀 worker.run((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9)(jobs chan closed) 🟥🟥🟥
        <--- 🚀 worker.run((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9) (SENT FINISHED). 🚀🚀🚀
  !!!! 🧊 WorkerPool.drain - worker((💚)WORKER-ID-3:6a50920c-0122-412f-9aa8-7c8eef623fd9) finished, remaining: '0' 🟥
  ===> 🧊 WorkerPool.run - drain complete (workers count: '0'). 🎃🎃🎃
  <--- WorkerPool.run (QUIT). 🧊🧊🧊
  <<<< 💠 consumer.run - new result arrived(#22): '                     ---> 🍉🍉🍉 [Seq: 21] Hello: '💩 poo''
  <<<< 💠 consumer.run - no more results available (running: false)
  <<<< consumer.run - finished (QUIT). 💠💠💠
  <--- orpheus(alpha) finished Counts >>> (Producer: '22', Consumer: '22'). 🎯🎯🎯
  << Captured StdOut/StdErr Output
------------------------------
 SUCCESS! 2.544103296s
[1691751653] I18n Suite - 0/0 specs - 7 procs  SUCCESS! 6.6546ms

@plastikfan
Copy link
Contributor Author

Another lesson to learn from this issue is that it's not necessary to always use a select statement with a ctx.Done() case. Actually, doing so may even cause problems as I discovered.

An example of this is in the worker.run method:

func (w *worker[I, R]) run(ctx context.Context) {
	defer func() {
		w.finishedChOut <- w.id // ⚠️ non-pre-emptive send, but this should be ok
		fmt.Printf("	<--- 🚀 worker.run(%v) (SENT FINISHED). 🚀🚀🚀\n", w.id)
	}()

This defer statement sends a finished notification to the pool, but there is little risk in this ever blocking because it is buffered with its capacity being set to the number of workers, ie there is space for every worker to send its finished notification. Because of this, the send does not need to be made pre-emptive by some other means.

So, do not make all interactions with channels pre-emptive, it depends on the situation at hand.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
feature New feature or request
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant