[JAVA] Low throughput in test in #YZ1

Challenges
1

Hi I have a issue with the remote tests.
There are one that depend from a previous test that set information in my redis, with a expiration time (100ms).
The issue here is that the new one run after 100 ms and don’t find anything because a thread with the remove task was run.

I know that my code works because of this script

#!/bin/bash
time redis-cli SET foo bar px 100
time redis-cli GET foo
time sleep 0.2 && redis-cli GET foo

and this is the output

OK

real    0m0.026s
user    0m0.000s
sys     0m0.000s
"bar"

real    0m0.019s
user    0m0.000s
sys     0m0.000s

real    0m0.214s
user    0m0.000s
sys     0m0.000s
(nil)
2

@agomezlucena can you share logs from the test runner please? Does it say that a nil value was returned for the first read (i.e. before the 100 ms sleep?)

3

Also, a link to your code would be helpful – hard to help without it

4

sure this is the repo [redacted]
and those are the logs

[compile] Compilation successful.

Debug = true

[tester::#YZ1] Running tests for Stage #YZ1 (Expiry)
[tester::#YZ1] $ ./spawn_redis_server.sh
[your_program] 18:31:59.486 [main] INFO  io.github.agomezlucena.Main -- loading custom redis server
[your_program] 18:31:59.511 [main] INFO  io.github.agomezlucena.Main -- server started
[tester::#YZ1] $ redis-cli SET grape banana px 100
[tester::#YZ1] Sent bytes: "*5\r\n$3\r\nSET\r\n$5\r\ngrape\r\n$6\r\nbanana\r\n$2\r\npx\r\n$3\r\n100\r\n"
[your_program] 18:31:59.619 [virtual-19] INFO  io.github.agomezlucena.Main -- handling petition for ip: /127.0.0.1:52640
[your_program] 18:31:59.625 [virtual-19] DEBUG i.g.agomezlucena.RedisCommandHandler -- reading command
[your_program] 18:31:59.628 [virtual-19] DEBUG i.g.agomezlucena.RedisCommandReader -- command read is finished
[your_program] 18:31:59.631 [virtual-19] DEBUG i.g.agomezlucena.RedisCommandReader -- raw command: *5\r\n$3\r\nSET\r\n$5\r\ngrape\r\n$6\r\nbanana\r\n$2\r\npx\r\n$3\r\n100\r\n
[your_program] 18:31:59.634 [virtual-19] DEBUG io.github.agomezlucena.Command -- extracting expiration in millis
[your_program] 18:31:59.634 [virtual-19] DEBUG io.github.agomezlucena.Command -- params: [BulkString[length=3, value=SET], BulkString[length=5, value=grape], BulkString[length=6, value=banana], BulkString[length=2, value=px], BulkString[length=3, value=100]]
[your_program] 18:31:59.662 [virtual-19] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=3, value=SET]
[your_program] 18:31:59.664 [virtual-19] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=5, value=grape]
[your_program] 18:31:59.664 [virtual-19] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=6, value=banana]
[your_program] 18:31:59.664 [virtual-19] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=2, value=px]
[your_program] 18:31:59.664 [virtual-19] DEBUG io.github.agomezlucena.Command -- found PX parameter checking if have values
[your_program] 18:31:59.664 [virtual-19] DEBUG io.github.agomezlucena.Command -- PX parameter have a value
[your_program] 18:31:59.665 [virtual-19] DEBUG i.g.agomezlucena.RedisCommandHandler -- executing command: SET with params: {CACHE_KEY=BulkString[length=5, value=grape], PAYLOAD=BulkString[length=6, value=banana], EXPIRATION_IN_MILLIS=BulkString[length=3, value=100]}
[tester::#YZ1] Received bytes: "+OK\r\n"
[tester::#YZ1] Received RESP simple string: "OK"
[tester::#YZ1] Received "OK"
[tester::#YZ1] Received OK at 18:31:59.667
[tester::#YZ1] Fetching key "grape" at 18:31:59.667 (should not be expired)
[tester::#YZ1] > GET grape
[tester::#YZ1] Sent bytes: "*2\r\n$3\r\nGET\r\n$5\r\ngrape\r\n"
[your_program] 18:31:59.666 [virtual-19] DEBUG i.g.agomezlucena.RedisCommandHandler -- result: +OK\r\n
[your_program] 18:31:59.767 [pool-1-thread-1] INFO  i.g.agomezlucena.RedisCommandHandler -- deleting from cache
[your_program] 18:31:59.767 [pool-1-thread-1] INFO  i.g.agomezlucena.RedisCommandHandler -- deleted cache for key: grape
[tester::#YZ1] Received: "" (no content received)
[tester::#YZ1]            ^ error
[tester::#YZ1] Error: Expected start of a new RESP2 value (either +, -, :, $ or *)
[tester::#YZ1] Test failed
[tester::#YZ1] Terminating program
[tester::#YZ1] Program terminated successfully
5

@agomezlucena the error here is actually a protocol error (no content received) - so I don’t think it has to do with timing. If it was just timing, then we’d see something like “Received NIL, expected grape”.

I wonder if the GET command just isn’t being parsed properly?

I see a log for the SET command:

executing command: SET with params

But I don’t see a corresponding one for GET. That’s not expected, is it?

6

That’s the issue for some reason it’s not calling to the service.
But when I use redis-cli works without any problem at least in my local machine.
Here you got all the logs after running my test.

20:33:43.169 [main] INFO  io.github.agomezlucena.Main -- loading custom redis server
20:33:43.195 [main] INFO  io.github.agomezlucena.Main -- server started
20:34:02.668 [virtual-21] INFO  io.github.agomezlucena.Main -- handling petition for ip: /127.0.0.1:51934
20:34:02.674 [virtual-21] DEBUG i.g.agomezlucena.RedisCommandHandler -- reading command
20:34:02.675 [virtual-21] DEBUG i.g.agomezlucena.RedisCommandReader -- command read is finished
20:34:02.679 [virtual-21] DEBUG i.g.agomezlucena.RedisCommandReader -- raw command: *5\r\n$3\r\nSET\r\n$5\r\napple\r\n$5\r\ngrape\r\n$2\r\npx\r\n$3\r\n100\r\n
20:34:02.683 [virtual-21] DEBUG io.github.agomezlucena.Command -- extracting expiration in millis
20:34:02.684 [virtual-21] DEBUG io.github.agomezlucena.Command -- params: [BulkString[length=3, value=SET], BulkString[length=5, value=apple], BulkString[length=5, value=grape], BulkString[length=2, value=px], BulkString[length=3, value=100]]
20:34:02.709 [virtual-21] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=3, value=SET]
20:34:02.709 [virtual-21] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=5, value=apple]
20:34:02.710 [virtual-21] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=5, value=grape]
20:34:02.710 [virtual-21] DEBUG io.github.agomezlucena.Command -- current: BulkString[length=2, value=px]
20:34:02.710 [virtual-21] DEBUG io.github.agomezlucena.Command -- found PX parameter checking if have values
20:34:02.710 [virtual-21] DEBUG io.github.agomezlucena.Command -- PX parameter have a value
20:34:02.711 [virtual-21] DEBUG i.g.agomezlucena.RedisCommandHandler -- executing command: SET with params: {CACHE_KEY=BulkString[length=5, value=apple], EXPIRATION_IN_MILLIS=BulkString[length=3, value=100], PAYLOAD=BulkString[length=5, value=grape]}
20:34:02.717 [virtual-21] DEBUG i.g.agomezlucena.RedisCommandHandler -- result: +OK\r\n
20:34:02.718 [virtual-21] INFO  io.github.agomezlucena.Main -- petition handled took: 50 ms
20:34:02.737 [virtual-26] INFO  io.github.agomezlucena.Main -- handling petition for ip: /127.0.0.1:51936
20:34:02.737 [virtual-26] DEBUG i.g.agomezlucena.RedisCommandHandler -- reading command
20:34:02.737 [virtual-26] DEBUG i.g.agomezlucena.RedisCommandReader -- command read is finished
20:34:02.739 [virtual-26] DEBUG i.g.agomezlucena.RedisCommandReader -- raw command: *2\r\n$3\r\nGET\r\n$5\r\napple\r\n
20:34:02.739 [virtual-26] DEBUG i.g.agomezlucena.RedisCommandHandler -- executing command: GET with params: {CACHE_KEY=BulkString[length=5, value=apple]}
20:34:02.740 [virtual-26] DEBUG i.g.agomezlucena.RedisCommandHandler -- retrieving key: apple
20:34:02.761 [virtual-26] DEBUG i.g.agomezlucena.RedisCommandHandler -- result: $5\r\ngrape\r\n
20:34:02.762 [virtual-26] INFO  io.github.agomezlucena.Main -- petition handled took: 25 ms
20:34:02.782 [virtual-27] INFO  io.github.agomezlucena.Main -- handling petition for ip: /127.0.0.1:51937
20:34:02.782 [virtual-27] DEBUG i.g.agomezlucena.RedisCommandHandler -- reading command
20:34:02.783 [virtual-27] DEBUG i.g.agomezlucena.RedisCommandReader -- command read is finished
20:34:02.783 [virtual-27] DEBUG i.g.agomezlucena.RedisCommandReader -- raw command: *2\r\n$3\r\nGET\r\n$5\r\napple\r\n
20:34:02.784 [virtual-27] DEBUG i.g.agomezlucena.RedisCommandHandler -- executing command: GET with params: {CACHE_KEY=BulkString[length=5, value=apple]}
20:34:02.784 [virtual-27] DEBUG i.g.agomezlucena.RedisCommandHandler -- retrieving key: apple
20:34:02.784 [virtual-27] DEBUG i.g.agomezlucena.RedisCommandHandler -- result: $5\r\ngrape\r\n
20:34:02.785 [virtual-27] INFO  io.github.agomezlucena.Main -- petition handled took: 3 ms
20:34:03.016 [virtual-28] INFO  io.github.agomezlucena.Main -- handling petition for ip: /127.0.0.1:51938
20:34:03.017 [virtual-28] DEBUG i.g.agomezlucena.RedisCommandHandler -- reading command
20:34:03.017 [virtual-28] DEBUG i.g.agomezlucena.RedisCommandReader -- command read is finished
20:34:03.018 [virtual-28] DEBUG i.g.agomezlucena.RedisCommandReader -- raw command: *2\r\n$3\r\nGET\r\n$5\r\napple\r\n
20:34:03.018 [virtual-28] DEBUG i.g.agomezlucena.RedisCommandHandler -- executing command: GET with params: {CACHE_KEY=BulkString[length=5, value=apple]}
20:34:03.019 [virtual-28] DEBUG i.g.agomezlucena.RedisCommandHandler -- retrieving key: apple
20:34:03.019 [virtual-28] DEBUG i.g.agomezlucena.RedisCommandHandler -- result: $-1\r\n
20:34:03.019 [virtual-28] INFO  io.github.agomezlucena.Main -- petition handled took: 3 ms
7

does test reuse connection? because that can be the problem

8

Yep, the tests do re-use connections (When this is not the case, you’ll see redis-cli <cmd> <args> as the log instead of just > <cmd> args)

9

This topic was automatically closed 5 days after the last reply. New replies are no longer allowed.