search

swisspost / vertx-redisques

A highly scalable redis-persistent queuing system for vertx
Other
13 stars 8 forks source link

Less optimal performance in QueueStatisticsCollector #188

Open hiddenalpha opened 3 weeks ago

hiddenalpha commented 3 weeks ago

(relates to (internal): SDCISA-16512)

2024-06-17T10:09:35,899 int houston WARN QueueStatisticsCollector - All those 4922 redis requests took 16033ms
2024-06-17T10:10:08,834 int houston WARN QueueStatisticsCollector - All those 4940 redis requests took 18970ms
2024-06-17T10:10:35,474 int houston WARN QueueStatisticsCollector - All those 4915 redis requests took 15610ms
2024-06-17T10:11:07,555 int houston WARN QueueStatisticsCollector - All those 4888 redis requests took 17691ms
2024-06-17T10:11:35,294 int houston WARN QueueStatisticsCollector - All those 4853 redis requests took 15430ms
2024-06-17T10:12:07,876 int houston WARN QueueStatisticsCollector - All those 4860 redis requests took 18012ms
2024-06-17T10:12:36,260 int houston WARN QueueStatisticsCollector - All those 4843 redis requests took 16396ms
2024-06-17T10:13:07,325 int houston WARN QueueStatisticsCollector - All those 4857 redis requests took 17461ms
2024-06-17T10:13:35,086 int houston WARN QueueStatisticsCollector - All those 4875 redis requests took 15222ms
2024-06-17T10:14:08,942 int houston WARN QueueStatisticsCollector - All those 4850 redis requests took 19067ms

Another 5'925 examples are available in attached log.

I could imagine that this can lead to timeouts in some callers.

Update (2024-06-21): Today I could observe some even more obscure ones. For whatever reason those took between 5 and 10 minutes to complete:

2024-06-21T09:53:48,442 int houston WARN QueueStatisticsCollector - All those 4238 redis requests took 328518ms
2024-06-21T09:54:41,537 int houston WARN QueueStatisticsCollector - All those 4206 redis requests took 351544ms
2024-06-21T09:55:41,550 int houston WARN QueueStatisticsCollector - All those 4205 redis requests took 351595ms
2024-06-21T09:56:05,351 int houston WARN QueueStatisticsCollector - All those 4248 redis requests took 345381ms
2024-06-21T09:57:21,414 int houston WARN QueueStatisticsCollector - All those 4242 redis requests took 301297ms
2024-06-21T09:59:04,350 int houston WARN QueueStatisticsCollector - All those 4165 redis requests took 374184ms
2024-06-21T10:00:00,952 int houston WARN QueueStatisticsCollector - All those 4215 redis requests took 400771ms
2024-06-21T10:00:17,936 int houston WARN QueueStatisticsCollector - All those 4238 redis requests took 537915ms
2024-06-21T10:00:48,603 int houston WARN QueueStatisticsCollector - All those 4178 redis requests took 418406ms
2024-06-21T10:00:50,857 int houston WARN QueueStatisticsCollector - All those 4156 redis requests took 360682ms
2024-06-21T10:00:55,701 int houston WARN QueueStatisticsCollector - All those 4153 redis requests took 305716ms
2024-06-21T11:46:18,132 int houston WARN QueueStatisticsCollector - All those 4533 redis requests took 448124ms
2024-06-21T11:47:53,475 int houston WARN QueueStatisticsCollector - All those 4570 redis requests took 483447ms
2024-06-21T11:49:45,074 int houston WARN QueueStatisticsCollector - All those 4534 redis requests took 505018ms
2024-06-21T11:50:14,786 int houston WARN QueueStatisticsCollector - All those 4590 redis requests took 504857ms
2024-06-21T11:51:06,692 int houston WARN QueueStatisticsCollector - All those 4593 redis requests took 496694ms
2024-06-21T11:51:24,244 int houston WARN QueueStatisticsCollector - All those 4569 redis requests took 484022ms
2024-06-21T11:51:33,691 int houston WARN QueueStatisticsCollector - All those 4626 redis requests took 343764ms
2024-06-21T11:52:26,886 int houston WARN QueueStatisticsCollector - All those 4638 redis requests took 456875ms
2024-06-21T11:52:37,037 int houston WARN QueueStatisticsCollector - All those 4588 redis requests took 376797ms
2024-06-21T11:52:46,667 int houston WARN QueueStatisticsCollector - All those 4597 redis requests took 446508ms
2024-06-21T11:53:33,925 int houston WARN QueueStatisticsCollector - All those 4596 redis requests took 553899ms
2024-06-21T11:54:42,852 int houston WARN QueueStatisticsCollector - All those 4613 redis requests took 442726ms
2024-06-21T11:55:19,160 int houston WARN QueueStatisticsCollector - All those 4610 redis requests took 449193ms
2024-06-21T11:56:51,017 int houston WARN QueueStatisticsCollector - All those 4611 redis requests took 600746ms
2024-06-21T11:57:11,031 int houston WARN QueueStatisticsCollector - All those 4607 redis requests took 471043ms
2024-06-21T11:57:16,220 int houston WARN QueueStatisticsCollector - All those 4591 redis requests took 446003ms
2024-06-21T11:57:17,783 int houston WARN QueueStatisticsCollector - All those 4573 redis requests took 507762ms
2024-06-21T11:57:21,206 int houston WARN QueueStatisticsCollector - All those 4608 redis requests took 421231ms
2024-06-21T11:57:27,584 int houston WARN QueueStatisticsCollector - All those 4626 redis requests took 367494ms
2024-06-21T11:57:27,873 int houston WARN QueueStatisticsCollector - All those 4607 redis requests took 397942ms
2024-06-21T11:57:29,509 int houston WARN QueueStatisticsCollector - All those 4603 redis requests took 339414ms
2024-06-21T13:19:46,890 int houston WARN QueueStatisticsCollector - All those 4678 redis requests took 326809ms
2024-06-21T13:20:58,400 int houston WARN QueueStatisticsCollector - All those 4717 redis requests took 308370ms
2024-06-21T13:22:12,706 int houston WARN QueueStatisticsCollector - All those 4699 redis requests took 322634ms
2024-06-21T13:22:37,573 int houston WARN QueueStatisticsCollector - All those 4643 redis requests took 317421ms
2024-06-21T13:23:36,564 int houston WARN QueueStatisticsCollector - All those 4655 redis requests took 316444ms
2024-06-21T13:24:30,851 int houston WARN QueueStatisticsCollector - All those 4666 redis requests took 310678ms
2024-06-21T13:25:53,060 int houston WARN QueueStatisticsCollector - All those 4681 redis requests took 483022ms
2024-06-21T13:31:40,549 int houston WARN QueueStatisticsCollector - All those 4642 redis requests took 650356ms
2024-06-21T13:31:49,917 int houston WARN QueueStatisticsCollector - All those 4641 redis requests took 569893ms
2024-06-21T13:31:55,071 int houston WARN QueueStatisticsCollector - All those 4552 redis requests took 425061ms
2024-06-21T13:31:57,841 int houston WARN QueueStatisticsCollector - All those 4571 redis requests took 337805ms
2024-06-21T13:31:58,421 int houston WARN QueueStatisticsCollector - All those 4536 redis requests took 308340ms
Kusig commented 1 week ago

Analysing the different Redis commands used, it looks as if hvals is the one taking the most of the time on the system. And it is only executed once during one statistic retrieval. See SDCISA-16512

Kusig commented 1 week ago

Turned out that there were very much keys within the corresponding hash table on Redis. Therefore, the delay observed here is quite logically and was caused by one single hvars call to Redis to retrieve the full Hashtable content.