with_advisory_lock
with_advisory_lock copied to clipboard
[Not a bug] Proper usage of with_advisory_lock
Hi! first off, thanks for the attention and for for the gem.
Rails: 5.0.0 psql (PostgreSQL) 10.3 (Debian 10.3-1.pgdg90+1)
My rails server is run inside a docker container with
bundle exec puma -t 0:5 -p ${PORT:-3000} -e ${RAILS_ENV:-development}
DB config has a pool of 5 threads as well
I am trying to figure out what I might be doing wrong in using this gem.
This is an excerpt of a service object
def call
Rails.logger.debug "Running thread #{Thread.current.object_id}"
ActiveRecord::Base.with_advisory_lock_result("backlog-lock", timeout_seconds: 5) do
if servicing.work_order.in_progress?
servicing.update(status: :open, redone: true, approval_status: nil)
else
servicing.rescheduled!
add_duplicated_servicing
backlog_work_order
end
end
end
This code gets executed as a result of a controller action, and to test I am executing two curl requests in parallel.
The behaviour I don't understand is that the second thread to reach the with_advisory_lock_result
seems to be blocking the first one, instead of just waiting for 5 seconds while the other thread keeps running.
The log output from executing the code above is:
Started POST "/api/servicings/92/reschedule?redo_reason=testing" for 172.18.0.1 at 2018-12-26 20:46:17 +0000
Started POST "/api/servicings/91/reschedule?redo_reason=testing" for 172.18.0.1 at 2018-12-26 20:46:17 +0000
Processing by API::ServicingsController#reschedule as */*
Parameters: {"redo_reason"=>"testing", "id"=>"91"}
Processing by API::ServicingsController#reschedule as */*
Parameters: {"redo_reason"=>"testing", "id"=>"92"}
User Load (1.6ms) SELECT "users".* FROM "users" WHERE "users"."deleted_at" IS NULL AND "users"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
User Load (7.7ms) SELECT "users".* FROM "users" WHERE "users"."deleted_at" IS NULL AND "users"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
Servicing Load (4.7ms) SELECT "servicings".* FROM "servicings" WHERE "servicings"."deleted_at" IS NULL AND "servicings"."id" = $1 LIMIT $2 [["id", 92], ["LIMIT", 1]]
CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."deleted_at" IS NULL AND "users"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
CACHE (0.3ms) SELECT "servicings".* FROM "servicings" WHERE "servicings"."deleted_at" IS NULL AND "servicings"."id" = $1 LIMIT $2 [["id", 92], ["LIMIT", 1]]
Servicing Load (9.5ms) SELECT "servicings".* FROM "servicings" WHERE "servicings"."deleted_at" IS NULL AND "servicings"."id" = $1 LIMIT $2 [["id", 91], ["LIMIT", 1]]
CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."deleted_at" IS NULL AND "users"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
CACHE (0.5ms) SELECT "servicings".* FROM "servicings" WHERE "servicings"."deleted_at" IS NULL AND "servicings"."id" = $1 LIMIT $2 [["id", 91], ["LIMIT", 1]]
(2.0ms) BEGIN
(2.8ms) BEGIN
(0.3ms) COMMIT
(0.4ms) COMMIT
Running thread 47076409369740
Running thread 69856980992120
(1.5ms) SELECT pg_try_advisory_lock(986825911,0) AS t3f11a179e210d135eade537bf1cf4340 /* backlog-lock */
(0.8ms) SELECT pg_try_advisory_lock(986825911,0) AS t27331309003857f07af7ba8c5d482a7f /* backlog-lock */
WorkOrder Load (11.5ms) SELECT "work_orders".* FROM "work_orders" WHERE "work_orders"."deleted_at" IS NULL AND "work_orders"."id" = $1 LIMIT $2 [["id", 39], ["LIMIT", 1]]
(1.3ms) BEGIN
(1.3ms) COMMIT
Location Load (3.5ms) SELECT "locations".* FROM "locations" WHERE "locations"."deleted_at" IS NULL AND "locations"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
WorkOrder Load (2.6ms) SELECT "work_orders".* FROM "work_orders" WHERE "work_orders"."deleted_at" IS NULL AND "work_orders"."status" IN ('open', 'in_progress') AND "work_orders"."backlog" = $1 AND "work_orders"."location_id" = 1 LIMIT $2 [["backlog", true], ["LIMIT", 1]]
(0.4ms) BEGIN
SQL (5.4ms) INSERT INTO "work_orders" ("contact", "location_id", "description", "backlog", "starts_at", "timezone", "ends_at", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id" [["contact", "Donato test"], ["location_id", 1], ["description", "Test"], ["backlog", true], ["starts_at", 2018-12-27 12:00:00 UTC], ["timezone", "America/New_York"], ["ends_at", 2018-12-27 18:00:00 UTC], ["created_at", 2018-12-26 20:46:18 UTC], ["updated_at", 2018-12-26 20:46:18 UTC]]
(3.9ms) COMMIT
(0.7ms) BEGIN
(0.5ms) COMMIT
Area Load (11.5ms) SELECT "areas".* FROM "areas" WHERE "areas"."deleted_at" IS NULL AND "areas"."id" = $1 LIMIT $2 [["id", 2], ["LIMIT", 1]]
(99.2ms) SELECT pg_try_advisory_lock(986825911,0) AS t00e16279f8d89a1b21ffe48bd6306f09 /* backlog-lock */
(1.1ms) SELECT pg_try_advisory_lock(986825911,0) AS tf3d6a44a3253fb07f24c8015b242f75b /* backlog-lock */
(1.3ms) SELECT pg_try_advisory_lock(986825911,0) AS tccae0e9b109ac8a5fa3dacabd26ea120 /* backlog-lock */
(0.7ms) SELECT pg_try_advisory_lock(986825911,0) AS t705f95fd6f580325093a5c300580671e /* backlog-lock */
(0.8ms) SELECT pg_try_advisory_lock(986825911,0) AS tbfeb8cd03aef66de28ea5193a5772ce2 /* backlog-lock */
(0.6ms) SELECT pg_try_advisory_lock(986825911,0) AS t331e00c084d8fd5f7bebfffb5e1ad7f0 /* backlog-lock */
(0.7ms) SELECT pg_try_advisory_lock(986825911,0) AS t33c88295291c7d1a319c46a7043d5115 /* backlog-lock */
(0.6ms) SELECT pg_try_advisory_lock(986825911,0) AS t1e5a62030123421fa68169c6bc3629c9 /* backlog-lock */
(0.6ms) SELECT pg_try_advisory_lock(986825911,0) AS t52bc53f618514af84bc297cdacc9d25a /* backlog-lock */
This last line goes on for the 5 seconds (parameter to with_advisory_lock_result
) and then it gives up -- no lock acquired -- and only then does the first thread resume work.
From the lines
Running thread 47076409369740
Running thread 69856980992120
(1.5ms) SELECT pg_try_advisory_lock(986825911,0) AS t3f11a179e210d135eade537bf1cf4340 /* backlog-lock */
(0.8ms) SELECT pg_try_advisory_lock(986825911,0) AS t27331309003857f07af7ba8c5d482a7f /* backlog-lock */
I presume that there are indeed 2 threads in parallel (different Thread.current.object_id
), almost in sync with each other.
I expected that I would see logs of the first thread doing its work intermingled with logs of the second thread querying the pg_try_advisory_lock, which does not seem to be the case.
Perhaps I am missing a parameter, or a db config in rails....