search

colinmollenhour / Cm_RedisSession

Redis-based session handler for Magento with optimistic locking
208 stars 121 forks source link

Long time request Redis lock #149

Closed ecommercearvatoprisma closed 6 years ago

ecommercearvatoprisma commented 6 years ago

hello, I have a problem with Redis, I have calls to URLS block ESI (Varnish) who are in "lock" and that for 3 seconds each time.

Example: 2018-06-25T15: 13: 11 + 00: 00 DEBUG (7): xxx | 5582: Waiting 0.51 second for lock on ID sess_73fps0bpfuj5jkj85mcjrtljo4 (1 tries, lock pid is, 0.00076 seconds elapsed) 2018-06-25T15: 13: 11 + 00: 00 DEBUG (7): xxx | 5582: Waiting 0.50 seconds for lock on ID sess_73fps0bpfuj5jkj85mcjrtljo4 (2 tries, lock pid is, 0.51152 seconds elapsed) 2018-06-25T15: 13: 12 + 00: 00 DEBUG (7): xxx | 5582: Waiting 0.50 seconds for lock on ID sess_73fps0bpfuj5jkj85mcjrtljo4 (3 tries, lock pid is, 1.01237 seconds elapsed) 2018-06-25T15: 13: 12 + 00: 00 DEBUG (7): xxx | 5582: Waiting 0.50 seconds for lock on ID sess_73fps0bpfuj5jkj85mcjrtljo4 (4 tries, lock pid is, 1.51343 seconds elapsed) 2018-06-25T15: 13: 13 + 00: 00 DEBUG (7): xxx | 5582: Waiting 0.50 seconds for lock on ID sess_73fps0bpfuj5jkj85mcjrtljo4 (5 tries, lock pid is, 2.01437 seconds elapsed) 2018-06-25T15: 13: 13 + 00: 00 DEBUG (7): xxx | 5582: Waiting 0.50 seconds for lock on ID sess_73fps0bpfuj5jkj85mcjrtljo4 (6 tries, lock pid is priweb102 | 5583, 2.51544 seconds elapsed) 2018-06-25T15: 13: 14 + 00: 00 DEBUG (7): xxx | 5582: Data read for ID sess_73fps0bpfuj5jkj85mcjrtljo4 in 0.00026 seconds 2018-06-25T15: 13: 14 + 00: 00 INFO (6): xxx | 5582: Successfully broke the lock for ID sess_73fps0bpfuj5jkj85mcjrtljo4 after 3.01729 seconds (6 attempts). Lock: 8 Last request of broken lock: GET xxxxx.xxxx.fr/turpentine/esi/getBlock/method/esi/access/

Why ?

How does the locks work?

What impacts if I disable?

Thank you Jérémy

colinmollenhour commented 6 years ago

You could probably sacrifice some locking without losing much by for example only using locking on POST requests or only on the block that renders session messages. To disable locking based on some logic use:

define('CM_REDISSESSION_LOCKING_ENABLED', FALSE);
ecommercearvatoprisma commented 6 years ago

Overall, what is the impact of locking? Today I have the problem that on "GET" calls. The block that will display the basket for example.

If I update a page, on the treatment of my session, I have this:

1531231433.032686 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231433.033097 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "1" 1531231433.543675 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231434.044319 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231434.544997 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231435.045654 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231435.546419 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231435.546792 [1 10.1.34.11:42657] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231436.047424 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231436.047848 [1 10.1.34.11:42657] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231436.048107 [1 10.1.34.11:42657] "hmget" "sess_trels648pibltkursim8bdelt3" "data" "writes" 1531231436.048546 [1 10.1.34.11:42657] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "-1" 1531231436.048802 [1 10.1.34.11:42657] "hget" "sess_trels648pibltkursim8bdelt3" "req" 1531231436.049158 [1 10.1.34.11:42657] "hmset" "sess_trels648pibltkursim8bdelt3" "pid" "xxxxx101|28662" "lock" "1" "req" "GET xxxxx.html" 1531231436.049212 [1 10.1.34.11:42657] "expire" "sess_trels648pibltkursim8bdelt3" "21600" 1531231437.905501 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231437.905847 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "1" 1531231438.416330 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231438.917020 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231439.417813 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231439.918561 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231440.419240 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231440.419901 [1 10.1.34.11:42663] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231440.920476 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231440.920831 [1 10.1.34.11:42663] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231440.921106 [1 10.1.34.11:42663] "hmget" "sess_trels648pibltkursim8bdelt3" "data" "writes" 1531231440.921544 [1 10.1.34.11:42663] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "-1" 1531231440.921813 [1 10.1.34.11:42663] "hget" "sess_trels648pibltkursim8bdelt3" "req" 1531231440.922222 [1 10.1.34.11:42663] "hmset" "sess_trels648pibltkursim8bdelt3" "pid" "xxxxx101|28471" "lock" "1" "req" "GET xxxxx/turpentine/esi/getBlock/method/esi/access/private/ttl/0/hmac/416b1f52ef0c961a6465fb9fe8734d8e1a7d31e649e5639614c2db3ff69ec6a1/data/nLeDNDfAAPT-NpRsk6UfLnE-IzC8TUSqLkMG_0uOrMm80qm4ZX86nwOyyw9FnlQor35OQFasEjiORqeh8n5GErSWj9LbczA4_9S63JDJLRuONXboSjGveU49ugN-kcXoTufX_7LYMWVwMGLkGVvokcGZxtfbjTnC0SiAehJ0S3ZpzjomEN5Z32XlTpGaigP2u-KaAF47o0My_7AYL7wm3ValyuVzBwxfQhw27TP-XFnz9agOMIT265fits4OQvXml0vfXK165T6B08PoF8xqK4KQfM-adjhuCHqlU9i-oocGOrtSS4yiw6P9lIBZQkNrF8-kQlLpf3prpZInR5eQhPYbuMnbMKGvMdzemkRLTMnQWTiimhii2g1aSJWTylFq8IB4DOqpEydBJp7v7xI24FoI3Yw9jss9IMqmzshqyaZBIwkr0IQ5QIUBGMeVKWCQkVl5yCDU8wYfwtXlMb2IzwGadIHDBTfFqMo_4Dm-jHQ=/r64/aHR0cHM6Ly9wcmVwcm9kLnByaXNtYXNob3AuZnIvdG91cy1sZXMtbWFnYXppbmVzL3Byb2dyYW1tZS10di90ZWxlLWxvaXNpcnMuaHRtbA,,/?id=19" 1531231440.922390 [1 10.1.34.11:42663] "expire" "sess_trels648pibltkursim8bdelt3" "21600" 1531231441.193316 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231441.193667 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "1" 1531231441.704208 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231442.204958 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231442.705761 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231443.206496 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231443.707223 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231443.707537 [1 10.1.34.11:42676] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231444.208046 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231444.208308 [1 10.1.34.11:42676] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231444.208575 [1 10.1.34.11:42676] "hmget" "sess_trels648pibltkursim8bdelt3" "data" "writes" 1531231444.208947 [1 10.1.34.11:42676] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "-1" 1531231444.209214 [1 10.1.34.11:42676] "hget" "sess_trels648pibltkursim8bdelt3" "req" 1531231444.209533 [1 10.1.34.11:42676] "hmset" "sess_trels648pibltkursim8bdelt3" "pid" "xxxxx101|28662" "lock" "1" "req" "GET xxxxx/turpentine/esi/getBlock/method/esi/access/private/ttl/0/hmac/bbe7a6e40446698a8ae8b359b0e300219ab2fd913ea613b694ddc3a81ba76685/data/CdTlMxr6fqc5wa0-KSLuPXnWGafpQDQJWWCIgnoM_9i_XNdHGatyvoL4f3bxLwRfZQYTRirziV-jnpLRCpeo_8YvZKehdkLUFlRKgqWyfrRERIgN4KFnUTiAoptT3OGybVGRiWnpRdyVNZ42aw1Nc11shL66LkIwJl39Wb22BwH9NcBAJ-CiOM0ysGn0yQkjHRc-aSaACvZA7fI6dGzfh4ldRHmckJzbcJGhH4mOkLBxFETwWwp4gAyjL_sYUIiv2YxzP-mC5vfvmJcNRkhQofDGQ3HyJBeMHS_ejHNNHRP1fvvc3GKhPMbfwneGTDCeejx6F0HmqV6liO9kABUZZ7rtLUq6JBTE-DsIuChcr51aEUmjlwgezW0uQrHcsUcmaGlWoXng-czh3jBLK44qF-s6AU7J8dwUDJMYk4ElaLsJZjhpk1lPVq8Crr7AZzBQ3WQ8UDuQPd9r_ATqK0j7vTeyFVLknevIy8xM78vsJ1w=/r64/aHR0cHM6Ly9wcmVwcm9kLnByaXNtYXNob3AuZnIv/" 1531231444.209714 [1 10.1.34.11:42676] "expire" "sess_trels648pibltkursim8bdelt3" "21600" 1531231444.437812 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231444.438036 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "1" 1531231444.948547 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231445.449215 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231445.949938 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231446.450802 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231446.951563 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231446.952035 [1 10.1.34.11:42695] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231447.452770 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231447.453235 [1 10.1.34.11:42695] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231447.453480 [1 10.1.34.11:42695] "hmget" "sess_trels648pibltkursim8bdelt3" "data" "writes" 1531231447.453963 [1 10.1.34.11:42695] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "-1" 1531231447.454219 [1 10.1.34.11:42695] "hget" "sess_trels648pibltkursim8bdelt3" "req" 1531231447.454582 [1 10.1.34.11:42695] "hmset" "sess_trels648pibltkursim8bdelt3" "pid" "xxxxx101|28472" "lock" "1" "req" "GET xxxxx/turpentine/esi/getBlock/method/esi/access/private/ttl/2678400/hmac/96a046c653a16df97487457c5286271720330d49c0bca5797433f79a12a6e67b/data/nHCxhQkCBdQA3VloaNk3kv55QV_8M0K67E0hcDEtv0rpE37JvJ38lQQGRSAqaLf8p0QuMohMmCFlpMfM5_IZfecJAH5L2EWZ6Qe9dYZbcMKUBJfJZyyZ2yQFfpqVQcJwYk4G6LZnMPaqcXslULNJgMEffGKtoRrVdVU-I6uN_jPfmuIVX7paXLaOZMq66gKN4gPnidkB95CUcJtS_AwUKfNxkRUnJcr47aCpM1pWVRIrRP6A_N4XDUnXqGNs4105MoH8OeMr9eD9zkv9-6lHgo2jm8kSnMyPZqaDL-rQnbojTMIX9-4zR3lC0eV68t0qOMxg1ERdCvx7n5Ps2qyhp69Fm36_QJYOR_xzJwxVk6cJ9UHGxGdveEJ6Q-ZmqZC8Gidv91RRMDF_DCQTi7Zg9g==/?id=19" 1531231447.454718 [1 10.1.34.11:42695] "expire" "sess_trels648pibltkursim8bdelt3" "21600" 1531231447.708821 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231447.709180 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "1" 1531231448.219682 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231448.720359 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231449.221035 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231449.721703 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231450.222436 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231450.222745 [1 10.1.34.11:42699] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231450.723422 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231450.723898 [1 10.1.34.11:42699] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231450.724275 [1 10.1.34.11:42699] "hmget" "sess_trels648pibltkursim8bdelt3" "data" "writes" 1531231450.724813 [1 10.1.34.11:42699] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "-1" 1531231450.725176 [1 10.1.34.11:42699] "hget" "sess_trels648pibltkursim8bdelt3" "req" 1531231450.725659 [1 10.1.34.11:42699] "hmset" "sess_trels648pibltkursim8bdelt3" "pid" "xxxxx101|28662" "lock" "1" "req" "GET xxxxx/turpentine/esi/getBlock/method/esi/access/private/ttl/2678400/hmac/23d94bdf97481c534696ee57e67a27393e800ab70bf119ccc2f440df430e78e5/data/0JkJtcR8z4mq9ItHEtDhxU3JSnAyXcHXS0rwYxO72FpG7PUUA7J-fEYkThYP9aBvtXboUm79SP9-6ufiFM9n5VNT-kV23nzotpsA_vLR0ttp8hJb4gNk35koA7febXxfb0ZVfhkFD7wpFztbIXh3kkarUcnQqEhNCwATwXYNs2ARlJEKBE226Tm97dLjM0JeNzCds6MORkEW6-Uj2bl5uQHA-6BfM6bmnERk-jD6crBdl3jNCf3aecjh_I2RbWDTsoOX2gxTJaCEnk5gtK9eJ4kV0qX3ecEnBYKUZcLvSBYUt_TldQlVP7FAeMe9YNjz77zm9rniDgZLXU-3FRtSlneaFP0jatu92kmFK4W_wHAMVpibg8JQlQ==/?id=19" 1531231450.725796 [1 10.1.34.11:42699] "expire" "sess_trels648pibltkursim8bdelt3" "21600" 1531231450.920313 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231450.920661 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "1" 1531231451.431236 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231451.931927 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231452.432737 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231452.933527 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231453.434746 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231453.435156 [1 10.1.34.11:42712] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231453.935702 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "lock" "1" 1531231453.936135 [1 10.1.34.11:42712] "hget" "sess_trels648pibltkursim8bdelt3" "pid" 1531231453.936396 [1 10.1.34.11:42712] "hmget" "sess_trels648pibltkursim8bdelt3" "data" "writes" 1531231453.936772 [1 10.1.34.11:42712] "hincrby" "sess_trels648pibltkursim8bdelt3" "wait" "-1" 1531231453.937026 [1 10.1.34.11:42712] "hget" "sess_trels648pibltkursim8bdelt3" "req" 1531231453.937427 [1 10.1.34.11:42712] "hmset" "sess_trels648pibltkursim8bdelt3" "pid" "xxxxx101|28471" "lock" "1" "req" "GET xxxxx/turpentine/esi/getBlock/method/esi/access/private/ttl/2678400/hmac/70b1c871567598743716aed86dbaeeb929c95600f24806d1e6eea03817fbe838/data/YH6yZUAnnX5L7Uh3aVMMklWdh7A-6jC_vOUh358XPrRdKmXUjwa3PfwY2bPQL_a853eI5KGlnt7gVIAtId4i6hdd_lTOwpmdQEctR2NVuuZB2p7mtbf9ysi7vyl9hIqg_dawT-kxtmL60O0yScK3mOGj9AxY2Fxg5TOV5DFyitc6q1Kw0YtNrLmZI8MDSmGEz-dHcVPhFY3VzsU62n__o1qMtSe9c0vPieKMKoLRNbdL4xgVNPmQJlVtt-VUonjHRvSlmhKr0WBVhYSHHLDYnwnQDxP0rDHHbjb7MI7tKwqTH_Nu3Zj6NexsIGK9QfFlK9MkZIfnfDIIhSX6qF5AZtT_jd6BzbRp5lGtWdUjdOgsIs02AI5SDxGAlI8vKvWA-j4Dl-1vlwZlKFCemKJUZw==/?id=19" 1531231453.937563 [1 10.1.34.11:42712] "expire" "sess_trels648pibltkursim8bdelt3" "21600"

colinmollenhour commented 6 years ago

Yeah if you're doing ESI I'd either disable locking entirely or only enable it on one block. It ensures that multiple requests are serialized and that session data does not get clobbered or modified by the wrong requests so if your blocks are only reading the session then you don't need locking on them.

tmotyl commented 5 years ago

see also https://github.com/colinmollenhour/Cm_RedisSession/issues/134 and https://github.com/colinmollenhour/Cm_RedisSession/pull/145 regarding possibility to set "FLAG_READ_ONLY"