Unpredictable time for queue.add to complete

Hello,

Is it normal for queue.add promise to resolve in a 1 - 10 seconds window ?

Redis is on the same host as client/workers
Redis database is almost empty
Its a dev server, there is no others queues/jobs running

The fime for queue.add to resolve feels very random

Sometimes it is very fast:

client log :
[2021-01-25 21:30:36.908 +0000] INFO (10357): await queue.add()
... 1 second ...
[2021-01-25 21:30:37.028 +0000] INFO (10357): queue.add completed, job.id is 47
[2021-01-25 21:30:38.052 +0000] INFO (10357): job.waitUntilFinished completed
[2021-01-25 21:30:38.053 +0000] INFO (10357): Job.fromId completed

worker log :
[2021-01-25 21:30:37.029 +0000] INFO (8284): job 47 started
[2021-01-25 21:30:38.042 +0000] INFO (8284): job 47 completed

And the next job it is very slow :

client log:
[2021-01-25 21:30:49.133 +0000] INFO (10357): await queue.add()
... 9 seconds ...
[2021-01-25 21:30:58.165 +0000] INFO (10357): queue.add completed, job.id is 48
[2021-01-25 21:30:59.191 +0000] INFO (10357): job.waitUntilFinished completed
[2021-01-25 21:30:59.192 +0000] INFO (10357): Job.fromId completed

worker log :
[2021-01-25 21:30:58.166 +0000] INFO (8284): job 48 started
[2021-01-25 21:30:59.181 +0000] INFO (8284): job 48 completed

Here is redis-monitor output of job 48

1611610259.187048 [0 lua] "EXISTS" "bull:metadata:48"
1611610259.187054 [0 lua] "GET" "bull:metadata:48:lock"
1611610259.187058 [0 lua] "DEL" "bull:metadata:48:lock"
1611610259.187063 [0 lua] "LREM" "bull:metadata:active" "-1" "48"
1611610259.187070 [0 lua] "ZADD" "bull:metadata:completed" "1611610259182" "48"

Here is my code :

log.info('await queue.add()')
const job = await queueMetadata.add('add', data)
log.info('queue.add completed, job.id is ' + job.id)
await job.waitUntilFinished(eventsMetadata)
log.info('job.waitUntilFinished completed')
const jobResult = await Job.fromId(queueMetadata, job.id!)
log.info('Job.fromId completed')

taskforcesh / bullmq

Unpredictable time for queue.add to complete #378