feat: support dequeue event to properly match enqueue counterpart

[odubuc]

Based on current event exposed, we can hook to
"connecttion" -> to know when a new connection is created in the pool
"acquire" -> to know when a connection was acquired from the pool
"release" -> to know when a connection was released back into the pool
"enqueue" -> to know when a query was sent to the pool and went to the queue to be processed later. ( > connectionLimit )

The problem arise when we want to know how the queue is doing. it's either going up and up and up with the enqueue event OR we can assume the queue is 0 when "release" is triggered.

Proposed change; a new "dequeue" event that is triggered every time a query is taken from "_connectionQueue" in the pool. This way metrics can be correctly plugged into mysql2 to know how fast the queue is unstacking.

Code to reproduce before and after the fix

/* eslint-disable no-console */
import { createPool } from "mysql2/promise";

let queuedCount = 0;
let activeCount = 0;

function timeStamp(message: string) {
    console.log("[" + new Date().toISOString().substring(11, 23) + "] -", message);
}

async function main() {
    const pool = createPool({
        host: "host",
        user: "user",
        password: "password",
        database: "database",
        waitForConnections: true,
        connectionLimit: 10,
        maxIdle: 10,
        enableKeepAlive: true,
    });

    pool.on("acquire", () => {
        activeCount++;
        timeStamp(`acquire : queued ${queuedCount}, active ${activeCount}`);
    });

    pool.on("connection", () => {
        timeStamp(`new connection created in pool`);
    });

    pool.on("enqueue", () => {
        queuedCount++;
        timeStamp(`enqueue : queued ${queuedCount}, active ${activeCount}`);
    });

    pool.on("dequeue", () => {
        queuedCount--;
        timeStamp(`dequeue : queued ${queuedCount}, active ${activeCount}`);
    });

    pool.on("release", () => {
        queuedCount = 0;
        activeCount--;
        timeStamp(`release : queued ${queuedCount}, active ${activeCount}`);
    });

    const todos = Array.from(Array(100).keys());

    timeStamp(`begin ${todos.length} query`);
    await Promise.all(
        todos.map(() => {
            return pool.query("SELECT sleep(5);");
        }),
    );
    timeStamp(`end ${todos.length} query`);

    await pool.end();
}

void main();

Logs that are shown before proposed changed

[20:15:36.339] - begin 100 query
[20:15:36.355] - enqueue : queued 1, active 0
[20:15:36.355] - enqueue : queued 2, active 0
[20:15:36.355] - enqueue : queued 3, active 0
[20:15:36.356] - enqueue : queued 4, active 0
[20:15:36.356] - enqueue : queued 5, active 0
[20:15:36.356] - enqueue : queued 6, active 0
[20:15:36.356] - enqueue : queued 7, active 0
[20:15:36.356] - enqueue : queued 8, active 0
[20:15:36.356] - enqueue : queued 9, active 0
[20:15:36.357] - enqueue : queued 10, active 0
[20:15:36.357] - enqueue : queued 11, active 0
[20:15:36.357] - enqueue : queued 12, active 0
[20:15:36.357] - enqueue : queued 13, active 0
[20:15:36.357] - enqueue : queued 14, active 0
[20:15:36.357] - enqueue : queued 15, active 0
[20:15:36.357] - enqueue : queued 16, active 0
[20:15:36.358] - enqueue : queued 17, active 0
[20:15:36.358] - enqueue : queued 18, active 0
[20:15:36.358] - enqueue : queued 19, active 0
[20:15:36.358] - enqueue : queued 20, active 0
[20:15:36.358] - enqueue : queued 21, active 0
[20:15:36.358] - enqueue : queued 22, active 0
[20:15:36.358] - enqueue : queued 23, active 0
[20:15:36.358] - enqueue : queued 24, active 0
[20:15:36.359] - enqueue : queued 25, active 0
[20:15:36.359] - enqueue : queued 26, active 0
[20:15:36.359] - enqueue : queued 27, active 0
[20:15:36.359] - enqueue : queued 28, active 0
[20:15:36.359] - enqueue : queued 29, active 0
[20:15:36.359] - enqueue : queued 30, active 0
[20:15:36.359] - enqueue : queued 31, active 0
[20:15:36.360] - enqueue : queued 32, active 0
[20:15:36.360] - enqueue : queued 33, active 0
[20:15:36.360] - enqueue : queued 34, active 0
[20:15:36.360] - enqueue : queued 35, active 0
[20:15:36.360] - enqueue : queued 36, active 0
[20:15:36.360] - enqueue : queued 37, active 0
[20:15:36.360] - enqueue : queued 38, active 0
[20:15:36.360] - enqueue : queued 39, active 0
[20:15:36.360] - enqueue : queued 40, active 0
[20:15:36.360] - enqueue : queued 41, active 0
[20:15:36.361] - enqueue : queued 42, active 0
[20:15:36.361] - enqueue : queued 43, active 0
[20:15:36.361] - enqueue : queued 44, active 0
[20:15:36.361] - enqueue : queued 45, active 0
[20:15:36.361] - enqueue : queued 46, active 0
[20:15:36.361] - enqueue : queued 47, active 0
[20:15:36.361] - enqueue : queued 48, active 0
[20:15:36.361] - enqueue : queued 49, active 0
[20:15:36.361] - enqueue : queued 50, active 0
[20:15:36.361] - enqueue : queued 51, active 0
[20:15:36.362] - enqueue : queued 52, active 0
[20:15:36.362] - enqueue : queued 53, active 0
[20:15:36.362] - enqueue : queued 54, active 0
[20:15:36.362] - enqueue : queued 55, active 0
[20:15:36.362] - enqueue : queued 56, active 0
[20:15:36.362] - enqueue : queued 57, active 0
[20:15:36.362] - enqueue : queued 58, active 0
[20:15:36.362] - enqueue : queued 59, active 0
[20:15:36.362] - enqueue : queued 60, active 0
[20:15:36.362] - enqueue : queued 61, active 0
[20:15:36.363] - enqueue : queued 62, active 0
[20:15:36.363] - enqueue : queued 63, active 0
[20:15:36.363] - enqueue : queued 64, active 0
[20:15:36.363] - enqueue : queued 65, active 0
[20:15:36.363] - enqueue : queued 66, active 0
[20:15:36.363] - enqueue : queued 67, active 0
[20:15:36.363] - enqueue : queued 68, active 0
[20:15:36.363] - enqueue : queued 69, active 0
[20:15:36.363] - enqueue : queued 70, active 0
[20:15:36.363] - enqueue : queued 71, active 0
[20:15:36.363] - enqueue : queued 72, active 0
[20:15:36.364] - enqueue : queued 73, active 0
[20:15:36.364] - enqueue : queued 74, active 0
[20:15:36.364] - enqueue : queued 75, active 0
[20:15:36.364] - enqueue : queued 76, active 0
[20:15:36.364] - enqueue : queued 77, active 0
[20:15:36.364] - enqueue : queued 78, active 0
[20:15:36.364] - enqueue : queued 79, active 0
[20:15:36.364] - enqueue : queued 80, active 0
[20:15:36.364] - enqueue : queued 81, active 0
[20:15:36.364] - enqueue : queued 82, active 0
[20:15:36.364] - enqueue : queued 83, active 0
[20:15:36.364] - enqueue : queued 84, active 0
[20:15:36.365] - enqueue : queued 85, active 0
[20:15:36.365] - enqueue : queued 86, active 0
[20:15:36.365] - enqueue : queued 87, active 0
[20:15:36.365] - enqueue : queued 88, active 0
[20:15:36.365] - enqueue : queued 89, active 0
[20:15:36.365] - enqueue : queued 90, active 0
[20:15:36.568] - new connection created in pool
[20:15:36.569] - acquire : queued 90, active 1
[20:15:36.569] - new connection created in pool
[20:15:36.570] - acquire : queued 90, active 2
[20:15:36.591] - new connection created in pool
[20:15:36.591] - acquire : queued 90, active 3
[20:15:36.592] - new connection created in pool
[20:15:36.592] - acquire : queued 90, active 4
[20:15:36.643] - new connection created in pool
[20:15:36.643] - acquire : queued 90, active 5
[20:15:36.675] - new connection created in pool
[20:15:36.675] - acquire : queued 90, active 6
[20:15:36.697] - new connection created in pool
[20:15:36.697] - acquire : queued 90, active 7
[20:15:36.725] - new connection created in pool
[20:15:36.725] - acquire : queued 90, active 8
[20:15:36.732] - new connection created in pool
[20:15:36.732] - acquire : queued 90, active 9
[20:15:36.751] - new connection created in pool
[20:15:36.751] - acquire : queued 90, active 10
[20:16:26.864] - release : queued 0, active 9
[20:16:26.960] - release : queued 0, active 8
[20:16:27.026] - release : queued 0, active 7
[20:16:27.168] - release : queued 0, active 6
[20:16:27.243] - release : queued 0, active 5
[20:16:27.244] - release : queued 0, active 4
[20:16:27.244] - release : queued 0, active 3
[20:16:27.244] - release : queued 0, active 2
[20:16:27.244] - release : queued 0, active 1
[20:16:27.311] - release : queued 0, active 0
[20:16:27.311] - end 100 query

logs after the proposed fix :

[20:37:46.187] - begin 100 query
[20:37:46.199] - enqueue : queued 1, active 0
[20:37:46.199] - enqueue : queued 2, active 0
[20:37:46.200] - enqueue : queued 3, active 0
[20:37:46.200] - enqueue : queued 4, active 0
[20:37:46.200] - enqueue : queued 5, active 0
[20:37:46.200] - enqueue : queued 6, active 0
[20:37:46.200] - enqueue : queued 7, active 0
[20:37:46.200] - enqueue : queued 8, active 0
[20:37:46.200] - enqueue : queued 9, active 0
[20:37:46.200] - enqueue : queued 10, active 0
[20:37:46.201] - enqueue : queued 11, active 0
[20:37:46.201] - enqueue : queued 12, active 0
[20:37:46.201] - enqueue : queued 13, active 0
[20:37:46.201] - enqueue : queued 14, active 0
[20:37:46.201] - enqueue : queued 15, active 0
[20:37:46.201] - enqueue : queued 16, active 0
[20:37:46.201] - enqueue : queued 17, active 0
[20:37:46.201] - enqueue : queued 18, active 0
[20:37:46.201] - enqueue : queued 19, active 0
[20:37:46.201] - enqueue : queued 20, active 0
[20:37:46.201] - enqueue : queued 21, active 0
[20:37:46.201] - enqueue : queued 22, active 0
[20:37:46.202] - enqueue : queued 23, active 0
[20:37:46.202] - enqueue : queued 24, active 0
[20:37:46.202] - enqueue : queued 25, active 0
[20:37:46.202] - enqueue : queued 26, active 0
[20:37:46.202] - enqueue : queued 27, active 0
[20:37:46.202] - enqueue : queued 28, active 0
[20:37:46.202] - enqueue : queued 29, active 0
[20:37:46.202] - enqueue : queued 30, active 0
[20:37:46.202] - enqueue : queued 31, active 0
[20:37:46.202] - enqueue : queued 32, active 0
[20:37:46.202] - enqueue : queued 33, active 0
[20:37:46.202] - enqueue : queued 34, active 0
[20:37:46.202] - enqueue : queued 35, active 0
[20:37:46.202] - enqueue : queued 36, active 0
[20:37:46.203] - enqueue : queued 37, active 0
[20:37:46.203] - enqueue : queued 38, active 0
[20:37:46.203] - enqueue : queued 39, active 0
[20:37:46.203] - enqueue : queued 40, active 0
[20:37:46.203] - enqueue : queued 41, active 0
[20:37:46.203] - enqueue : queued 42, active 0
[20:37:46.203] - enqueue : queued 43, active 0
[20:37:46.203] - enqueue : queued 44, active 0
[20:37:46.203] - enqueue : queued 45, active 0
[20:37:46.203] - enqueue : queued 46, active 0
[20:37:46.203] - enqueue : queued 47, active 0
[20:37:46.203] - enqueue : queued 48, active 0
[20:37:46.203] - enqueue : queued 49, active 0
[20:37:46.203] - enqueue : queued 50, active 0
[20:37:46.203] - enqueue : queued 51, active 0
[20:37:46.203] - enqueue : queued 52, active 0
[20:37:46.203] - enqueue : queued 53, active 0
[20:37:46.203] - enqueue : queued 54, active 0
[20:37:46.204] - enqueue : queued 55, active 0
[20:37:46.204] - enqueue : queued 56, active 0
[20:37:46.204] - enqueue : queued 57, active 0
[20:37:46.204] - enqueue : queued 58, active 0
[20:37:46.204] - enqueue : queued 59, active 0
[20:37:46.204] - enqueue : queued 60, active 0
[20:37:46.204] - enqueue : queued 61, active 0
[20:37:46.204] - enqueue : queued 62, active 0
[20:37:46.204] - enqueue : queued 63, active 0
[20:37:46.204] - enqueue : queued 64, active 0
[20:37:46.204] - enqueue : queued 65, active 0
[20:37:46.204] - enqueue : queued 66, active 0
[20:37:46.204] - enqueue : queued 67, active 0
[20:37:46.204] - enqueue : queued 68, active 0
[20:37:46.204] - enqueue : queued 69, active 0
[20:37:46.204] - enqueue : queued 70, active 0
[20:37:46.204] - enqueue : queued 71, active 0
[20:37:46.204] - enqueue : queued 72, active 0
[20:37:46.205] - enqueue : queued 73, active 0
[20:37:46.205] - enqueue : queued 74, active 0
[20:37:46.205] - enqueue : queued 75, active 0
[20:37:46.205] - enqueue : queued 76, active 0
[20:37:46.205] - enqueue : queued 77, active 0
[20:37:46.205] - enqueue : queued 78, active 0
[20:37:46.205] - enqueue : queued 79, active 0
[20:37:46.205] - enqueue : queued 80, active 0
[20:37:46.205] - enqueue : queued 81, active 0
[20:37:46.205] - enqueue : queued 82, active 0
[20:37:46.205] - enqueue : queued 83, active 0
[20:37:46.205] - enqueue : queued 84, active 0
[20:37:46.205] - enqueue : queued 85, active 0
[20:37:46.205] - enqueue : queued 86, active 0
[20:37:46.205] - enqueue : queued 87, active 0
[20:37:46.205] - enqueue : queued 88, active 0
[20:37:46.205] - enqueue : queued 89, active 0
[20:37:46.205] - enqueue : queued 90, active 0
[20:37:46.420] - new connection created in pool
[20:37:46.420] - acquire : queued 90, active 1
[20:37:46.421] - new connection created in pool
[20:37:46.421] - acquire : queued 90, active 2
[20:37:46.443] - new connection created in pool
[20:37:46.443] - acquire : queued 90, active 3
[20:37:46.443] - new connection created in pool
[20:37:46.443] - acquire : queued 90, active 4
[20:37:46.483] - new connection created in pool
[20:37:46.483] - acquire : queued 90, active 5
[20:37:46.499] - new connection created in pool
[20:37:46.499] - acquire : queued 90, active 6
[20:37:46.513] - new connection created in pool
[20:37:46.513] - acquire : queued 90, active 7
[20:37:46.529] - new connection created in pool
[20:37:46.529] - acquire : queued 90, active 8
[20:37:46.542] - new connection created in pool
[20:37:46.543] - acquire : queued 90, active 9
[20:37:46.571] - new connection created in pool
[20:37:46.571] - acquire : queued 90, active 10
[20:37:51.453] - dequeue : queued 89, active 10
[20:37:51.475] - dequeue : queued 88, active 10
[20:37:51.475] - dequeue : queued 87, active 10
[20:37:51.475] - dequeue : queued 86, active 10
[20:37:51.565] - dequeue : queued 85, active 10
[20:37:51.566] - dequeue : queued 84, active 10
[20:37:51.566] - dequeue : queued 83, active 10
[20:37:51.566] - dequeue : queued 82, active 10
[20:37:51.587] - dequeue : queued 81, active 10
[20:37:51.609] - dequeue : queued 80, active 10
[20:37:56.483] - dequeue : queued 79, active 10
[20:37:56.508] - dequeue : queued 78, active 10
[20:37:56.508] - dequeue : queued 77, active 10
[20:37:56.508] - dequeue : queued 76, active 10
[20:37:56.647] - dequeue : queued 75, active 10
[20:37:56.648] - dequeue : queued 74, active 10
[20:37:56.648] - dequeue : queued 73, active 10
[20:37:56.648] - dequeue : queued 72, active 10
[20:37:56.648] - dequeue : queued 71, active 10
[20:37:56.649] - dequeue : queued 70, active 10
[20:38:01.508] - dequeue : queued 69, active 10
[20:38:01.599] - dequeue : queued 68, active 10
[20:38:01.599] - dequeue : queued 67, active 10
[20:38:01.599] - dequeue : queued 66, active 10
[20:38:01.683] - dequeue : queued 65, active 10
[20:38:01.683] - dequeue : queued 64, active 10
[20:38:01.684] - dequeue : queued 63, active 10
[20:38:01.684] - dequeue : queued 62, active 10
[20:38:01.684] - dequeue : queued 61, active 10
[20:38:01.684] - dequeue : queued 60, active 10
[20:38:06.534] - dequeue : queued 59, active 10
[20:38:06.628] - dequeue : queued 58, active 10
[20:38:06.628] - dequeue : queued 57, active 10
[20:38:06.629] - dequeue : queued 56, active 10
[20:38:06.752] - dequeue : queued 55, active 10
[20:38:06.752] - dequeue : queued 54, active 10
[20:38:06.753] - dequeue : queued 53, active 10
[20:38:06.753] - dequeue : queued 52, active 10
[20:38:06.753] - dequeue : queued 51, active 10
[20:38:06.753] - dequeue : queued 50, active 10
[20:38:11.558] - dequeue : queued 49, active 10
[20:38:11.666] - dequeue : queued 48, active 10
[20:38:11.666] - dequeue : queued 47, active 10
[20:38:11.667] - dequeue : queued 46, active 10
[20:38:11.791] - dequeue : queued 45, active 10
[20:38:11.792] - dequeue : queued 44, active 10
[20:38:11.792] - dequeue : queued 43, active 10
[20:38:11.792] - dequeue : queued 42, active 10
[20:38:11.792] - dequeue : queued 41, active 10
[20:38:11.793] - dequeue : queued 40, active 10
[20:38:16.584] - dequeue : queued 39, active 10
[20:38:16.693] - dequeue : queued 38, active 10
[20:38:16.717] - dequeue : queued 37, active 10
[20:38:16.717] - dequeue : queued 36, active 10
[20:38:16.877] - dequeue : queued 35, active 10
[20:38:16.877] - dequeue : queued 34, active 10
[20:38:16.877] - dequeue : queued 33, active 10
[20:38:16.877] - dequeue : queued 32, active 10
[20:38:16.878] - dequeue : queued 31, active 10
[20:38:16.878] - dequeue : queued 30, active 10
[20:38:21.611] - dequeue : queued 29, active 10
[20:38:21.719] - dequeue : queued 28, active 10
[20:38:21.747] - dequeue : queued 27, active 10
[20:38:21.747] - dequeue : queued 26, active 10
[20:38:21.911] - dequeue : queued 25, active 10
[20:38:21.911] - dequeue : queued 24, active 10
[20:38:21.912] - dequeue : queued 23, active 10
[20:38:21.912] - dequeue : queued 22, active 10
[20:38:21.937] - dequeue : queued 21, active 10
[20:38:21.937] - dequeue : queued 20, active 10
[20:38:26.636] - dequeue : queued 19, active 10
[20:38:26.748] - dequeue : queued 18, active 10
[20:38:26.845] - dequeue : queued 17, active 10
[20:38:26.846] - dequeue : queued 16, active 10
[20:38:26.941] - dequeue : queued 15, active 10
[20:38:26.964] - dequeue : queued 14, active 10
[20:38:26.965] - dequeue : queued 13, active 10
[20:38:26.965] - dequeue : queued 12, active 10
[20:38:26.965] - dequeue : queued 11, active 10
[20:38:26.965] - dequeue : queued 10, active 10
[20:38:31.663] - dequeue : queued 9, active 10
[20:38:31.772] - dequeue : queued 8, active 10
[20:38:31.887] - dequeue : queued 7, active 10
[20:38:31.887] - dequeue : queued 6, active 10
[20:38:31.976] - dequeue : queued 5, active 10
[20:38:32.001] - dequeue : queued 4, active 10
[20:38:32.002] - dequeue : queued 3, active 10
[20:38:32.002] - dequeue : queued 2, active 10
[20:38:32.002] - dequeue : queued 1, active 10
[20:38:32.002] - dequeue : queued 0, active 10
[20:38:36.694] - release : queued 0, active 9
[20:38:36.802] - release : queued 0, active 8
[20:38:36.910] - release : queued 0, active 7
[20:38:36.976] - release : queued 0, active 6
[20:38:37.057] - release : queued 0, active 5
[20:38:37.057] - release : queued 0, active 4
[20:38:37.057] - release : queued 0, active 3
[20:38:37.058] - release : queued 0, active 2
[20:38:37.058] - release : queued 0, active 1
[20:38:37.058] - release : queued 0, active 0
[20:38:37.058] - end 100 query

[wellwelwel]

LGTM 🚀

[ashleybartlett]

Any chance of getting this one merged?

[odubuc]

Not sure what is holding the merge. This is my first PR on this repo