user question: Does it also take 200-300ms to connect with a Redis client in your tests?

[kmuthukk]

PING 176.xxxxxxx (176xxxxxx) 56(84) bytes of data.
64 bytes from 176.xxxxxxx: icmp_seq=1 ttl=64 time=0.018 ms
64 bytes from 176.xxxxxxx: icmp_seq=2 ttl=64 time=0.027 ms

[root@yb1 ~]# time redis-cli -h 176.xxxxxx -a xxxxxxxxxxxxxxxxxxxxxxxxxxxxx info
# Server
redis_version:999.999.999
# Replication
role:master
connected_slaves:0
master_replid:0000000000000000000000000000000000000000
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:0
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

real    0m0.270s
user    0m0.001s
sys     0m0.001s```

`real    0m0.270s`

[kmuthukk]

@amitanandaiyer - was able to reproduce this.

Without "auth" (-a) option it is pretty fast. First time about 30ms, and then subsequent times even faster like 3ms:

19:18 $ time ./redis-cli -h 10.9.123.137 info
# Server
redis_version:999.999.999
# Replication
role:master
connected_slaves:0
master_replid:0000000000000000000000000000000000000000
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:0
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

real    0m0.030s
user    0m0.000s
sys     0m0.001s

19:18 $ time ./redis-cli -h 10.9.123.137 info
# Server
redis_version:999.999.999
# Replication
role:master
connected_slaves:0
master_replid:0000000000000000000000000000000000000000
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:0
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

real    0m0.003s
user    0m0.000s

With AUTH turned on:

19:19 $ time ./redis-cli -h 10.9.123.137
10.9.123.137:6379> CONFIG SET requirepass "yugapass"
OK

And now, the initial connect takes about 250ms. See two runs below:

19:20 $ time ./redis-cli -h 10.9.123.137 -a yugapass info
# Server
redis_version:999.999.999
# Replication
role:master
connected_slaves:0
master_replid:0000000000000000000000000000000000000000
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:0
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

real    0m0.254s
user    0m0.000s
sys     0m0.002s


19:20 $ time ./redis-cli -h 10.9.123.137 -a yugapass info
# Server
redis_version:999.999.999
# Replication
role:master
connected_slaves:0
master_replid:0000000000000000000000000000000000000000
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:0
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

real    0m0.255s
user    0m0.002s
sys     0m0.000s

Perhaps not super urgent, but would be good to understand why the initially connect with AUTH on is significantly more expensive.

[amitanandaiyer]

@kmuthukk it looks like the delay is due to computing the hash for the stored password using crypt_blowfish/

W0325 23:35:45.812889  5442 redis_rpc.cc:284] redis_details {
  call_details {
    redis_string: " AUTH foobared"
  }
}
Trace:
W0325 23:35:45.812899  5442 redis_rpc.cc:285] 0325 23:35:45.529333 (+     0us) inbound_call.cc:89] Created InboundCall
0325 23:35:45.529352 (+    19us) service_pool.cc:141] Inserting onto call queue
0325 23:35:45.529397 (+    45us) service_pool.cc:212] Handling call
0325 23:35:45.529434 (+    37us) redis_service.cc:1400] virtual yb::Status yb::redisserver::{anonymous}::RedisServiceImplData::GetRedisPasswords(std::vector<std::basic_string<char> >*)
0325 23:35:45.529436 (+     2us) redis_service.cc:1407] Returning
0325 23:35:45.529440 (+     4us) redis_commands.cc:1062] void yb::redisserver::{anonymous}::HandleAuth(yb::redisserver::{anonymous}::LocalCommandData)
0325 23:35:45.529441 (+     1us) redis_service.cc:1400] virtual yb::Status yb::redisserver::{anonymous}::RedisServiceImplData::GetRedisPasswords(std::vector<std::basic_string<char> >*)
0325 23:35:45.529442 (+     1us) redis_service.cc:1407] Returning
0325 23:35:45.529455 (+    13us) redis_commands.cc:996] bool yb::redisserver::{anonymous}::AcceptPassword(const std::vector<std::basic_string<char> >&, const string&)
0325 23:35:45.529455 (+     0us) redis_commands.cc:998] next pwd
0325 23:35:45.529456 (+     1us) crypt.cc:105] int yb::util::bcrypt_checkpw(const char*, const char*)
0325 23:35:45.529456 (+     0us) crypt.cc:87] crypt_rn
0325 23:35:45.812634 (+283178us) crypt.cc:89] crypt_rn done
0325 23:35:45.812641 (+     7us) crypt.cc:110] hashed

Although not recommended, setting --use_hashed_redis_password to false we see that the latencies are down to ~35ms again.

Trial 1 with authentication
PONG

real    0m0.036s
user    0m0.016s
sys     0m0.016s
Trial 2 with authentication
PONG

real    0m0.038s
user    0m0.014s
sys     0m0.019s
Trial 3 with authentication
PONG

real    0m0.038s
user    0m0.018s
sys     0m0.016s
Trial 4 with authentication
PONG

real    0m0.037s
user    0m0.015s
sys     0m0.018s
Trial 5 with authentication
PONG

real    0m0.035s
user    0m0.017s
sys     0m0.015s