[ioredis] Can't get consistent durations on get/set in a loop

[Daniel Vanzin]

Hi, I'm trying to get some performance data in order to choose when to use redis, but I can't seem to get a consistent benchmark result.

I'm comparing the durations (ms) of a mongoose find, redis set/get with parsing an object (6kb text) and redis get/set with a long value:

mongoFind [6.800445,4.400399,3.351903,31.413145,83.322476,87.343173,62.329214,2.742115,1.852713,2.542614]
redisSetObject [2.873609,2.091907,10.87749,0.884921,1.191235,2.332975,1.021124,0.822983,1.055066,1.176622]
redisGetObject [1.900724,1.239943,1.382232,1.126001,0.554803,0.699953,0.714505,0.482456,0.506765,0.64612]
redisSetLong [0.779387,0.571763,0.440567,0.803045,2.436041,4.322287,17.469914,0.312463,0.388022,0.46824]
redisGetLong [0.700649,0.881971,5.043164,0.741424,0.884584,0.807541,1.255212,0.280573,0.359213,0.518526]

Can somebody explain me why such disparities between iterations? I was expecting minimum variation in redis and also get/set long to be faster than get/set object. Some variations I tried:

- single runs: makes the mongo results more consistent

- get/set long first: it seemed to become faster then get/set object, but not always, still big discrepancies.

I'm using https://github.com/luin/ioredis and a dockerized environment. Here is my code:

const perfTest = function* () {

for (let i = 0; i < 10; i++) {

start = process.hrtime();

const company = yield Companies.findOne({ cod: 'a000001' });

// console.log('DDV', process.hrtime(start)[1] / 1000000);

durations.mongoFind.push(process.hrtime(start)[1] / 1000000);

start = process.hrtime();

yield redisClient.setex('testObject', 3600, JSON.stringify(company));

durations.redisSetObject.push(process.hrtime(start)[1] / 1000000);

start = process.hrtime();

yield redisClient.setex('testLong', 3600, Date.now());

durations.redisSetLong.push(process.hrtime(start)[1] / 1000000);

start = process.hrtime();

let parsedCompany = yield redisClient.get('testObject');

parsedCompany = JSON.parse(parsedCompany);

durations.redisGetObject.push(process.hrtime(start)[1] / 1000000);

start = process.hrtime();

let dateTime = yield redisClient.get('testLong');

durations.redisGetLong.push(process.hrtime(start)[1] / 1000000);

}

};

Thanks

[Kyle Davis]

Unusual results, although I'm seeing huger variations in Mongo (response times from 1.8 to 87!) too which leads me to believe it's more in the nature of your script or environment than the server(s). Off hand, could you be seeing GC pauses? Not sure if anything else is going on in your script.

Also it's a small sample size - run a few thousand iterations and it might be more enlightening. I would also be curious to know if callbacks are appreciably faster than the ES6 generators. 

-Kyle

[Daniel Vanzin]

Yeah, my test had a problem. Here is a more precise result (colored in the attach file)

mongoFind       avg 1.905 min 1.099 max 5.267  2.424 3.469 2.045 2.936 1.657 2.164 5.267 1.750 1.655 1.695 1.312 1.668 1.805 1.895 1.357 1.758 2.436 1.694 2.569 1.320 2.431 1.406 1.246 1.206 1.099 1.153 1.830 1.415 1.214 1.270
redisSetObject  avg 0.753 min 0.472 max 2.091  1.006 1.270 1.427 0.641 0.583 0.721 0.689 0.635 0.733 0.721 0.605 1.039 2.091 0.711 0.616 0.726 0.691 0.734 0.757 0.564 0.649 0.540 0.553 0.497 0.472 0.607 0.600 0.540 0.500 0.664
redisGetObject  avg 0.475 min 0.326 max 1.519  0.394 0.760 1.519 0.327 0.337 0.674 0.357 0.326 0.448 0.352 0.344 0.802 0.969 0.365 0.349 0.388 0.356 0.560 0.367 0.430 0.497 0.345 0.347 0.328 0.328 0.479 0.363 0.331 0.342 0.461
redisSetLong    avg 0.323 min 0.216 max 1.092  0.355 0.656 1.092 0.226 0.222 0.225 0.235 0.222 0.266 0.243 0.259 0.808 0.256 0.226 0.225 0.256 0.240 0.234 0.294 0.291 0.273 0.230 0.226 0.219 0.216 0.308 0.225 0.224 0.245 0.696

redisGetLong    avg 0.276 min 0.204 max 1.001  0.247 0.366 1.001 0.209 0.208 0.255 0.219 0.219 0.264 0.231 0.257 0.379 0.422 0.210 0.221 0.288 0.225 0.250 0.217 0.295 0.244 0.217 0.206 0.207 0.204 0.320 0.213 0.231 0.216 0.247

Still curious about the variation. Don't know much about GC pauses, I kind of understand the concept. Any way to eliminate this as a variable? Increase number of DB connections, do a warm up, or something?

Regarding generators, they perform the same as promises. I had an ~60% increase in performance on my kind of heavy on promises code going from node 6 to 8. I remember making some tests to compare node 6 promise vs callback, callbacks were ~20% faster I think. But I started using bluebird during this time, don't quite remember how much that skewed my tests.

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To unsubscribe from this group and stop receiving emails from it, send an email to redis-db+unsubscribe@googlegroups.com.
To post to this group, send email to redi...@googlegroups.com.
Visit this group at https://groups.google.com/group/redis-db.
For more options, visit https://groups.google.com/d/optout.

--

Att.,

Daniel Vanzin - Desenvolvimento de Software (48) 4052-9834 www.ahgora.com.br

[Daniel Vanzin]

BTW, this is 100
mongoFind       avg 1.467 min 1.032 max 4.839
redisSetObject  avg 0.629 min 0.463 max 2.325
redisGetObject  avg 0.367 min 0.311 max 0.874
redisSetLong    avg 0.258 min 0.206 max 1.621
redisGetLong    avg 0.247 min 0.195 max 0.948

1000
mongoFind       avg 1.251 min 0.922 max 5.129
redisSetObject  avg 0.556 min 0.437 max 3.398
redisGetObject  avg 0.353 min 0.280 max 3.304
redisSetLong    avg 0.235 min 0.172 max 2.725

redisGetLong    avg 0.220 min 0.170 max 2.966

10000

mongoFind       avg 1.246 min 0.841 max 8.016
redisSetObject  avg 0.623 min 0.432 max 6.040
redisGetObject  avg 0.383 min 0.275 max 6.955
redisSetLong    avg 0.251 min 0.165 max 4.653
redisGetLong    avg 0.253 min 0.159 max 6.031

[The Real Bill]

Just a tip on the results: To get a more clear picture, I'd drop the average and analyze it based on percentiles instead. When the gap between min and max is significant (which multiple factors of min is certainly a significant gap), the average is essentially useless. This is is especially true in smaller batches, such as only 100-10,000. Running 90,95, and 99th percentiles instead will give you a more realistic set of bounds to operate with. Combining standard deviation with, say, a 95th percentile would provide a good basis for monitoring for outliers and performance changes you (or an ops team) may want to investigate. Having that data available to put into a histogram can be useful in identifying the number possible causes and in confirming their rectification.

To unsubscribe from this group and stop receiving emails from it, send an email to redis-db+u...@googlegroups.com.

To post to this group, send email to redi...@googlegroups.com.
Visit this group at https://groups.google.com/group/redis-db.
For more options, visit https://groups.google.com/d/optout.

--

Att.,

Daniel Vanzin - Desenvolvimento de Software (48) 4052-9834 www.ahgora.com.br

[Damon L.]

@TheRealBill : great response thanks for the tip. This is going into my Best Practice notebook :)