tonyskn / node-redis-timeseries

Redis time series statistics with Node.js
MIT License
181 stars 27 forks source link

Concurrency issue with pendingMulti variable #5

Closed thanosa75 closed 10 years ago

thanosa75 commented 10 years ago

I am writing a piece of code to increase/store counters and hitting it with average load. In some cases I get the strange behaviour that a specific counter is increased by an extra digit - 2-3 every 250. This is in a transactional multithreaded environment and node app is being hit by at least 3-10 concurrent hits.

I've checked MONITOR output and in all my cases, situation is similar to the below:

1390991605.597054 "MULTI"
1390991605.597119 "hget" "cmp:2_11223300050:w:1389830400" "1389830400"
1390991605.597149 "hget" "cmp:2_11223300050:w:1389830400" "1390435200"
1390991605.597158 "EXEC"
1390991605.597315 "MULTI"
1390991605.597383 "hincrby" "cmp:2_11223300055:d:1390867200" "1390953600" "1"
1390991605.597395 "expireat" "cmp:2_11223300055:d:1390867200" "1391212800"
1390991605.597405 "EXEC"
1390991605.597632 "MULTI"
1390991605.597739 "hincrby" "cmp:2_11223300055:d:1390867200" "1390953600" "1"
1390991605.597754 "expireat" "cmp:2_11223300055:d:1390867200" "1391212800"
1390991605.597766 "hincrby" "cmp:2_11223300053:d:1390867200" "1390953600" "1"
1390991605.597777 "expireat" "cmp:2_11223300053:d:1390867200" "1391212800"
1390991605.597789 "EXEC"

Problematic behaviour (additional +1) comes at the point marked with timestamps 1390991605.597383 and 1390991605.597739. It seems that the "pendingMulti" variable is picked up by the next event without it being cleared by the previous caller, due to high concurrency.

Code used to create the issue is part of an express() application, function to record the hit is as below:

// this POST request records 1 hit for (now)
// on all granularities defined
app.post('/hit/:rule/:type/:id', function(req,res) {
        var tsKey = req.params.id ;
        var dataMap = { ver : PROTO, tp: req.params.rule };
        ts = getTS(req.params.rule,req.params.type);
        if (ts == null) { // not found or invalid rule given
                dataMap['error'] = 'not a correct rule/type:'+req.params.rule+','+req.params.type;
                res.json(404,dataMap);
                return;
        }
        //console.log("selected = "+ts.keyBase);
        ts.recordHit(tsKey).exec(function(err,result) {
                if (err != null) {
                        console.log("ERROR writing redis "+err);
                        res.json(404, err);
                }
                //console.log("Recorded hit ", ++hitCounter, new Date());
                res.json(200, dataMap);
        });
});
tonyskn commented 10 years ago

Hey,

This should be fixed in 0.3.1, which I just pushed to npm