pcp icon indicating copy to clipboard operation
pcp copied to clipboard

Published 20 hours ago • verified publisher icon performancecopilot

pmseries query to redis via pmproxy triggers assert in redisProcessCallBacks()

Open goodwinos opened this issue 5 years ago • 1 comments 

$ pmseries -Dseries -p 44323 kernel.all.pswitch
...
pmseries: [Debug] Connection established
    metric.name
==
    "kernel.all.pswitch"
Baton [query/0x56315c415480] references: 0 -> 1 (@ series_query_services)
Baton [query/0x56315c415480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x56315c415480] references: 0 -> 1 (@ series_query_maps)
Baton [query/0x56315c415480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x56315c415480] references: 0 -> 1 (@ series_query_eval)
Baton [query/0x56315c415480] references: 1 -> 2 (@ series_prepare_expr[direct])
Redis [slot=16316] SMEMBERS pcp:series:metric.name:b23b0b8c0277ba9db64019494f6e51f549a6ee83
Redis [slot=16316] localhost:44323
Baton [query/0x56315c415480] references: 2 -> 1 (@ series_query_end_phase[seriesPassBaton])
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x56315c414ea0
|REPLY type=array elements=1
[0]||REPLY type=string len=20 SID d7832c4fba33bcc980b1a1b614e0508043288480
metric pcp:series:metric.name:b23b0b8c0277ba9db64019494f6e51f549a6ee83
    d7832c4fba33bcc980b1a1b614e0508043288480
Union of large(1) and small(0) series
Baton [query/0x56315c415480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x56315c415480] references: 0 -> 1 (@ series_query_expr)
Baton [query/0x56315c415480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x56315c415480] references: 0 -> 1 (@ series_query_mapping)
Redis [slot=08367] HGETALL pcp:map:metric.name
Redis [slot=08367] localhost:44323
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x56315c414ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x56315c414ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x56315c414ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x56315c414ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x56315c414ea0
|REPLY type=array elements=2410

... 2409 reply elements omitted ...
Baton [query/0x56315c415480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x56315c415480] references: 0 -> 1 (@ series_query_desc)
Baton [query/0x56315c415480] references: 1 -> 2 (@ series_node_get_desc)
Redis [slot=13646] HMGET pcp:desc:series:d7832c4fba33bcc980b1a1b614e0508043288480
Redis [slot=13646] localhost:44323
Baton [query/0x56315c415480] references: 2 -> 3 (@ series_node_get_metric_name)
Redis [slot=12402] SMEMBERS pcp:metric.name:series:d7832c4fba33bcc980b1a1b614e0508043288480
Redis [slot=12402] localhost:44323
Baton [query/0x56315c415480] references: 3 -> 2 (@ series_query_end_phase[seriesPassBaton])
__redisAsyncDisconnect: ERROR 3 "Server closed the connection"

The assert happens after the SMEMBERS request from series_node_get_metric_name(), and we never get to series_query_report_matches().

In pmproxy's log (with -Dseries,query) ... lots omitted ...

Redis [slot=00000] HMGET (null)
Redis [slot=00000] localhost:6379
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x56277fd4bcd0
|REPLY type=array elements=5
[0]||REPLY type=string len=4 "none"
[1]||REPLY type=string len=7 "counter"
[2]||REPLY type=string len=20 SID 6864a34c58c4d3b1f59abf8aa8633538eb3c2c6c
[3]||REPLY type=string len=3 "u64"
[4]||REPLY type=string len=5 "count"
|REPLY type=array elements=1
[0]||REPLY type=string len=20 SID b23b0b8c0277ba9db64019494f6e51f549a6ee83
pmproxy: redis.c:1868: redisProcessCallBacks: Assertion `(c->flags & REDIS_SUBSCRIBED || c->flags & REDIS_MONITORING)' failed.

Running the same pmseries query directly to redis (on port 6379) works fine:

$ pmseries -p 6379 kernel.all.pswitch
d7832c4fba33bcc980b1a1b614e0508043288480

and with diags :

$ pmseries -p 6379 -Dseries kernel.all.pswitch
Slot range: 00000-16384
    Master: localhost:6379
Baton [slots/0x55a3ed5aeac0] references: 0 -> 1 (@ redis_load_slots)
Redis [slot=00000] CLUSTER (null)
Redis [slot=00000] localhost:6379
Connected to Redis on localhost:6379
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b74a0
|REPLY type=error len=46 "ERR This instance has cluster support disabled"
Baton [slots/0x55a3ed5aeac0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
Baton [slots/0x55a3ed5aeac0] references: 0 -> 1 (@ redis_load_version)
Redis [slot=00000] INFO (null)
Redis [slot=00000] localhost:6379
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7640
|REPLY type=string len=494 "# Server
redis_version:5.0.9
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:699c550ace009f13
redis_mode:standalone
os:Linux 5.8.16-200.fc32.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:10.1.1
process_id:1726810
run_id:91c5467df646c6bce73235a02634c3268dfeaa4e
tcp_port:6379
uptime_in_seconds:76515
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:10183630
executable:/usr/bin/redis-server
config_file:/etc/redis.conf
"
Baton [slots/0x55a3ed5aeac0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
Baton [slots/0x55a3ed5aeac0] references: 0 -> 1 (@ redis_load_series_version)
Redis [slot=12804] GET pcp:version:schema
Redis [slot=12804] localhost:6379
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7bb0
|REPLY type=string len=1 "2"
Baton [slots/0x55a3ed5aeac0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
Baton [slots/0x55a3ed5aeac0] references: 0 -> 1 (@ redis_load_search_schema)
Redis [slot=05044] FT.CREATE pcp:text
Redis [slot=05044] localhost:6379
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7ea0
|REPLY type=error len=191 "ERR unknown command `FT.CREATE`, with args beginning with: `pcp:text`, `SCHEMA`, `TYPE`, `TAG`, `SORTABLE`, `NAME`, `TEXT`, `WEIGHT`, `9`, `SORTABLE`, `INDOM`, `TAG`, `ONELINE`, `TEXT`, `W`, "
Baton [slots/0x55a3ed5aeac0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
pmseries: [Debug] Connection established
    metric.name
==
    "kernel.all.pswitch"
Baton [query/0x55a3ed5b8480] references: 0 -> 1 (@ series_query_services)
Baton [query/0x55a3ed5b8480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x55a3ed5b8480] references: 0 -> 1 (@ series_query_maps)
Baton [query/0x55a3ed5b8480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x55a3ed5b8480] references: 0 -> 1 (@ series_query_eval)
Baton [query/0x55a3ed5b8480] references: 1 -> 2 (@ series_prepare_expr[direct])
Redis [slot=16316] SMEMBERS pcp:series:metric.name:b23b0b8c0277ba9db64019494f6e51f549a6ee83
Redis [slot=16316] localhost:6379
Baton [query/0x55a3ed5b8480] references: 2 -> 1 (@ series_query_end_phase[seriesPassBaton])
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7ea0
|REPLY type=array elements=1
[0]||REPLY type=string len=20 SID d7832c4fba33bcc980b1a1b614e0508043288480
metric pcp:series:metric.name:b23b0b8c0277ba9db64019494f6e51f549a6ee83
    d7832c4fba33bcc980b1a1b614e0508043288480
Union of large(1) and small(0) series
Baton [query/0x55a3ed5b8480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x55a3ed5b8480] references: 0 -> 1 (@ series_query_expr)
Baton [query/0x55a3ed5b8480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x55a3ed5b8480] references: 0 -> 1 (@ series_query_mapping)
Redis [slot=08367] HGETALL pcp:map:metric.name
Redis [slot=08367] localhost:6379
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7ea0
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed5b7ea0
|REPLY type=array elements=2410
... omitted
Baton [query/0x55a3ed5b8480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x55a3ed5b8480] references: 0 -> 1 (@ series_query_desc)
Baton [query/0x55a3ed5b8480] references: 1 -> 2 (@ series_node_get_desc)
Redis [slot=13646] HMGET pcp:desc:series:d7832c4fba33bcc980b1a1b614e0508043288480
Redis [slot=13646] localhost:6379
Baton [query/0x55a3ed5b8480] references: 2 -> 3 (@ series_node_get_metric_name)
Redis [slot=12402] SMEMBERS pcp:metric.name:series:d7832c4fba33bcc980b1a1b614e0508043288480
Redis [slot=12402] localhost:6379
Baton [query/0x55a3ed5b8480] references: 3 -> 2 (@ series_query_end_phase[seriesPassBaton])
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x55a3ed630b00
|REPLY type=array elements=5
[0]||REPLY type=string len=4 "none"
[1]||REPLY type=string len=7 "counter"
[2]||REPLY type=string len=20 SID 6864a34c58c4d3b1f59abf8aa8633538eb3c2c6c
[3]||REPLY type=string len=3 "u64"
[4]||REPLY type=string len=5 "count"
Baton [query/0x55a3ed5b8480] references: 2 -> 1 (@ series_query_end_phase[seriesPassBaton])
|REPLY type=array elements=1
[0]||REPLY type=string len=20 SID b23b0b8c0277ba9db64019494f6e51f549a6ee83
Baton [query/0x55a3ed5b8480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x55a3ed5b8480] references: 0 -> 1 (@ series_query_report_matches)
d7832c4fba33bcc980b1a1b614e0508043288480
Baton [query/0x55a3ed5b8480] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
redisSlotServerFree: localhost:6379
Disconnected from redis on localhost:6379

goodwinos avatar Oct 30 '20 00:10 goodwinos

Post what I got here:

pmseries -Dseries -p 44323 kernel.all.pswitch
Slot range: 00000-16384
    Master: localhost:44323
Baton [slots/0x1b875d0] references: 0 -> 1 (@ redis_load_slots)
Redis [slot=00000] CLUSTER (null)
Redis [slot=00000] localhost:44323
Connected to Redis on localhost:44323
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x1b87c90
|REPLY type=error len=46 "ERR This instance has cluster support disabled"
Baton [slots/0x1b875d0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
Baton [slots/0x1b875d0] references: 0 -> 1 (@ redis_load_version)
Redis [slot=00000] INFO (null)
Redis [slot=00000] localhost:44323
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x1b87c90
|REPLY type=string len=519 "# Server
redis_version:6.0.8
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:8af2e20209bd5615
redis_mode:standalone
os:Linux 4.4.0-93-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:5.4.0
process_id:9805
run_id:d09c805bd9c06981bdde1af821f2d3a3fe64c6e6
tcp_port:6379
uptime_in_seconds:3857930
uptime_in_days:44
hz:10
configured_hz:10
lru_clock:10302542
executable:/usr/local/bin/redis-server
config_file:/etc/redis/6379.conf
io_threads_active:0
"
Baton [slots/0x1b875d0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
Baton [slots/0x1b875d0] references: 0 -> 1 (@ redis_load_series_version)
Redis [slot=12804] GET pcp:version:schema
Redis [slot=12804] localhost:44323
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x1b877b0
|REPLY type=string len=1 "2"
Baton [slots/0x1b875d0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
Baton [slots/0x1b875d0] references: 0 -> 1 (@ redis_load_search_schema)
Redis [slot=05044] FT.CREATE pcp:text
Redis [slot=05044] localhost:44323
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x1b877b0
|REPLY type=error len=191 "ERR unknown command `FT.CREATE`, with args beginning with: `pcp:text`, `SCHEMA`, `TYPE`, `TAG`, `SORTABLE`, `NAME`, `TEXT`, `WEIGHT`, `9`, `SORTABLE`, `INDOM`, `TAG`, `ONELINE`, `TEXT`, `W`, "
Baton [slots/0x1b875d0] references: 1 -> 0 (@ redis_slots_end_phase[seriesPassBaton])
pmseries: [Debug] Connection established
    metric.name
==
    "kernel.all.pswitch"
Baton [query/0x1b8abe0] references: 0 -> 1 (@ series_query_services)
Baton [query/0x1b8abe0] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x1b8abe0] references: 0 -> 1 (@ series_query_maps)
Baton [query/0x1b8abe0] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x1b8abe0] references: 0 -> 1 (@ series_query_eval)
Baton [query/0x1b8abe0] references: 1 -> 2 (@ series_prepare_expr[direct])
Redis [slot=16316] SMEMBERS pcp:series:metric.name:b23b0b8c0277ba9db64019494f6e51f549a6ee83
Redis [slot=16316] localhost:44323
Baton [query/0x1b8abe0] references: 2 -> 1 (@ series_query_end_phase[seriesPassBaton])
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x1b877b0
|REPLY type=array elements=1
[0]||REPLY type=string len=20 SID 555af91f8b192251e4655d77d5073c45c9b46f1c
metric pcp:series:metric.name:b23b0b8c0277ba9db64019494f6e51f549a6ee83
    555af91f8b192251e4655d77d5073c45c9b46f1c
Union of large(1) and small(0) series
Baton [query/0x1b8abe0] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x1b8abe0] references: 0 -> 1 (@ series_query_expr)
Baton [query/0x1b8abe0] references: 1 -> 0 (@ series_query_end_phase[seriesPassBaton])
Baton [query/0x1b8abe0] references: 0 -> 1 (@ series_query_mapping)
Redis [slot=08367] HGETALL pcp:map:metric.name
Redis [slot=08367] localhost:44323
CALLBACK redisProcessCallBacks: flags=0x0202 replies=0x1b8a840
__redisAsyncDisconnect: ERROR 4 "Protocol error, got "m" as reply type byte"

ElephantZhang avatar Oct 31 '20 09:10 ElephantZhang

This was resolved in PCP v6 with the transition to hiredis-cluster and some followup fixes from @andreasgerstmayr

natoscott avatar Oct 13 '22 00:10 natoscott