Problem with MySQL when trying to consume #413

sonofsounds · 2023-10-19T10:00:47Z

sonofsounds
Oct 19, 2023

Hello, I am building a Java application using SpringBoot and I have the following problem when using MySQLSelectForUpdateBasedProxyManager. I created an endpoint "/rate-limiter" whose primary purpose is to rate limit per API key.
The problem is that the tryConsumeAndReturnRemaining method takes too much time to respond. (5-6 seconds). I will attach the code below:

SQLProxyConfiguration<Long> sqlProxyConfiguration = SQLProxyConfiguration.builder()
                .build(dataSource);
        MySQLSelectForUpdateBasedProxyManager proxyManager = new MySQLSelectForUpdateBasedProxyManager(sqlProxyConfiguration);

        BucketConfiguration bucketConfiguration = BucketConfiguration.builder()
                .addLimit(limit -> limit.capacity(3).refillIntervally(3, ofMinutes(1)))
                .build();
        BucketProxy bucket = proxyManager.builder().build(apiKey, bucketConfiguration);

        long now = System.currentTimeMillis();
        ConsumptionProbe remaining = bucket.tryConsumeAndReturnRemaining(1);
        _logger.info("Time to fetch bucket: " +  (System.currentTimeMillis() - now));
        if (remaining.isConsumed()) {

            return ResponseEntity.ok("Success." + remaining.getRemainingTokens());
        }

        return ResponseEntity.status(HttpStatus.TOO_MANY_REQUESTS).body("Too many requests" + TimeUnit.NANOSECONDS.toSeconds(remaining.getNanosToWaitForRefill()));

The dataSource comes with Spring Boot and it is Hikari.

What could be the problem? @vladimir-bukhtoyarov

vladimir-bukhtoyarov · 2023-10-19T11:41:23Z

vladimir-bukhtoyarov
Oct 19, 2023
Maintainer

@sonofsounds
MySQL integration is implemented in on class https://github.com/bucket4j/bucket4j/blob/master/bucket4j-mysql/src/main/java/io/github/bucket4j/mysql/MySQLSelectForUpdateBasedProxyManager.java

You can just copy it to your project and add more logs, just modify each method of SelectForUpdateBasedTransaction for collect time of operation https://github.com/bucket4j/bucket4j/blob/master/bucket4j-mysql/src/main/java/io/github/bucket4j/mysql/MySQLSelectForUpdateBasedProxyManager.java#L82C20-L82C51

2 replies

sonofsounds Oct 19, 2023
Author

Hello, I have some logs from MySQL it seems that the commit time is taking too long.

Thu Oct 19 13:23:52 EEST 2023 INFO: [QUERY] SET autocommit=0 [Created on: Thu Oct 19 13:23:52 EEST 2023, duration: 32, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)] Thu Oct 19 13:23:52 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:52 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)] Thu Oct 19 13:23:52 EEST 2023 INFO: [QUERY] SELECT state FROM bucket WHERE id = 999999999 FOR UPDATE [Created on: Thu Oct 19 13:23:52 EEST 2023, duration: 32, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)] Thu Oct 19 13:23:52 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:52 EEST 2023, duration: 0, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)] Thu Oct 19 13:23:52 EEST 2023 INFO: [QUERY] INSERT IGNORE INTO bucket(id, state) VALUES(999999999, null) [Created on: Thu Oct 19 13:23:52 EEST 2023, duration: 32, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)] Thu Oct 19 13:23:52 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:52 EEST 2023, duration: 0, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)] **_Thu Oct 19 13:23:58 EEST 2023 INFO: [QUERY] commit [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 6423, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:377)]_** Thu Oct 19 13:23:58 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:377)] Thu Oct 19 13:23:58 EEST 2023 INFO: [QUERY] SET autocommit=1 [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 31, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.PoolBase.resetConnectionState(PoolBase.java:214)] Thu Oct 19 13:23:58 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.PoolBase.resetConnectionState(PoolBase.java:214)] Thu Oct 19 13:23:58 EEST 2023 INFO: [QUERY] SET autocommit=0 [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 32, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)] Thu Oct 19 13:23:58 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)] Thu Oct 19 13:23:58 EEST 2023 INFO: [QUERY] SELECT state FROM bucket WHERE id = 999999999 FOR UPDATE [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 32, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)] Thu Oct 19 13:23:58 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:58 EEST 2023, duration: 0, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)] Thu Oct 19 13:23:59 EEST 2023 INFO: [QUERY] rollback [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 31, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:385)] Thu Oct 19 13:23:59 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:385)] Thu Oct 19 13:23:59 EEST 2023 INFO: [QUERY] SET autocommit=1 [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 31, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.PoolBase.resetConnectionState(PoolBase.java:214)] Thu Oct 19 13:23:59 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.PoolBase.resetConnectionState(PoolBase.java:214)] Thu Oct 19 13:23:59 EEST 2023 INFO: [QUERY] SET autocommit=0 [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 32, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)] Thu Oct 19 13:23:59 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)] Thu Oct 19 13:23:59 EEST 2023 INFO: [QUERY] SELECT state FROM bucket WHERE id = 999999999 FOR UPDATE [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 34, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)] Thu Oct 19 13:23:59 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 0, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)] Thu Oct 19 13:23:59 EEST 2023 INFO: [QUERY] UPDATE bucket SET state=x'00000001000000010000000100000001000000000000000300000000000000030000000df847580000000000000000030180000000000000000000000000030000000100000003178f7b31fa20488000000000000000020000000000000000000000010000000000000001' WHERE id=999999999 [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 32, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)] Thu Oct 19 13:23:59 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 0, connection-id: 44072, statement-id: 0, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)] Thu Oct 19 13:23:59 EEST 2023 INFO: [QUERY] commit [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 142, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:377)] Thu Oct 19 13:23:59 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:377)] Thu Oct 19 13:23:59 EEST 2023 INFO: [QUERY] SET autocommit=1 [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 35, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.PoolBase.resetConnectionState(PoolBase.java:214)] Thu Oct 19 13:23:59 EEST 2023 INFO: [FETCH] [Created on: Thu Oct 19 13:23:59 EEST 2023, duration: 0, connection-id: 44072, statement-id: -1, resultset-id: 0, at com.zaxxer.hikari.pool.PoolBase.resetConnectionState(PoolBase.java:214)]

Do you know what can cause this problem? I tested with another db from another server and the response time decreases significantly. (200-1000ms)

sonofsounds Oct 19, 2023
Author

@vladimir-bukhtoyarov

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Problem with MySQL when trying to consume #413

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 1 comment 2 replies

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

Select a reply

Problem with MySQL when trying to consume #413

sonofsounds Oct 19, 2023

Replies: 1 comment · 2 replies

vladimir-bukhtoyarov Oct 19, 2023 Maintainer

sonofsounds Oct 19, 2023 Author

sonofsounds Oct 19, 2023 Author

sonofsounds
Oct 19, 2023

Replies: 1 comment 2 replies

vladimir-bukhtoyarov
Oct 19, 2023
Maintainer

sonofsounds Oct 19, 2023
Author

sonofsounds Oct 19, 2023
Author