Ensuring we produce a valid JSON in case of empty string and -nan #273

filipecosta90 · 2024-11-07T01:29:20Z

We can reproduce easily with:

memtier_benchmark --command "DEBUG SLEEP 2" --json-out-file 2secs.json -n 10 -c 1 -t 1

Fixes [bug] Output file sometimes contains invalid JSON (-nan, inf) #271
Fixes per second latency metrics are skeweed on very long running commands. #272
Add test for valid JSON format

To confirm the issue is fixed, we've added a test that previously generated bad JSON.

TEST=tests_oss_simple_flow:test_valid_json_using_debug_command VERBOSE=1 ./tests/run_tests.sh

old output:

{
	"configuration":{
		"server": "localhost"
		,"port": 6379
		,"unix socket": "(null)"
		,"address family": "Unspecified"
		,"protocol": "redis"
		,"out_file": "(null)"
		,"tls": "false"
		,"cert": "(null)"
		,"key": "(null)"
		,"cacert": "(null)"
		,"tls_skip_verify": "false"
		,"sni": "(null)"
		,"client_stats": "(null)"
		,"run_count": 1
		,"debug": 0
		,"requests": 3
		,"rate_limit": 0
		,"clients": 1
		,"threads": 1
		,"test_time": 0
		,"ratio": "1:10"
		,"pipeline": 1
		,"data_size": 32
		,"data_offset": 0
		,"random_data": "false"
		,"data_size_range": "0:0"
		,"data_size_list": ""
		,"data_size_pattern": "R"
		,"expiry_range": "0:0"
		,"data_import": "(null)"
		,"data_verify": "false"
		,"verify_only": "false"
		,"generate_keys": "false"
		,"key_prefix": "memtier-"
		,"key_minimum":           0
		,"key_maximum":    10000000
		,"key_pattern": "R:R"
		,"key_stddev": 0.000000
		,"key_median": 0.000000
		,"reconnect_interval": 0
		,"multi_key_get": 0
		,"authenticate": ""
		,"select-db": 0
		,"no-expiry": "false"
		,"wait-ratio": "0:0"
		,"num-slaves": "0:0"
		,"wait-timeout": "0-0"
		}
	,"run information":{
		"Threads": 1
		,"Connections per thread": 1
		,"Requests per client": 3
		,"Format version": 2
		}
	,"ALL STATS":{
		"Runtime":{
			"Start time": 1730996242002
			,"Finish time": 1730996248003
			,"Total duration": 6001
			,"Time unit": "MILLISECONDS"
			}
		,"Debugs":{
			"Count": 0
			,"Ops/sec": 0.50
			,"Hits/sec": 0.00
			,"Misses/sec": 0.00
			,"Latency": 0.000
			,"Average Latency": 0.000
			,"Min Latency": 0.000
			,"Max Latency": 0.000
			,"KB/sec": 0.02
			,"KB/sec RX/TX": 0.02
			,"KB/sec RX": 0.00
			,"KB/sec TX": 0.02
			,"Time-Serie":{
				"0":{
					"Bytes RX": 0
					,"Bytes TX": 0
					,"Count": 0
					}
				,"2":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": -nan
					,"Min Latency": 9223372036854776.000
					,"Max Latency": 0.000
					,"p50.00": 0.000
					,"p99.00": 0.000
					,"p99.90": 0.000
					}
				,"4":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": -nan
					,"Min Latency": 9223372036854776.000
					,"Max Latency": 0.000
					,"p50.00": 0.000
					,"p99.00": 0.000
					,"p99.90": 0.000
					}
				,"6":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": -nan
					,"Min Latency": 9223372036854776.000
					,"Max Latency": 0.000
					,"p50.00": 0.000
					,"p99.00": 0.000
					,"p99.90": 0.000
					}
				}
			,"Percentile Latencies":{
				"p50.00": 0.000
				,"p99.00": 0.000
				,"p99.90": 0.000
				,"Histogram log format":{
					"Compressed Histogram": "HISTFAAAACB4nJNpmSzMwMDAyAABTFCaC0zyOznYf4AIMAIAQ0gDFQ=="
					}
				}
			}
		,"Totals":{
			"Count": 0
			,"Ops/sec": 0.50
			,"Hits/sec": 0.00
			,"Misses/sec": 0.00
			,"Latency": 0.000
			,"Average Latency": 0.000
			,"Min Latency": 0.000
			,"Max Latency": 0.000
			,"KB/sec": 0.04
			,"KB/sec RX/TX": 0.04
			,"KB/sec RX": 0.02
			,"KB/sec TX": 0.02
			,"Time-Serie":{
				"0":{
					"Bytes RX": 0
					,"Bytes TX": 0
					,"Count": 0
					}
				,"2":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": -nan
					,"Min Latency": 9223372036854776.000
					,"Max Latency": 0.000
					,"p50.00": 0.000
					,"p99.00": 0.000
					,"p99.90": 0.000
					}
				,"4":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": -nan
					,"Min Latency": 9223372036854776.000
					,"Max Latency": 0.000
					,"p50.00": 0.000
					,"p99.00": 0.000
					,"p99.90": 0.000
					}
				,"6":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": -nan
					,"Min Latency": 9223372036854776.000
					,"Max Latency": 0.000
					,"p50.00": 0.000
					,"p99.00": 0.000
					,"p99.90": 0.000
					}
				}
			,"Percentile Latencies":{
				"p50.00": 0.000
				,"p99.00": 0.000
				,"p99.90": 0.000
				,"Histogram log format":{
					"Compressed Histogram": "HISTFAAAACB4nJNpmSzMwMDAyAABTFCaC0zyOznYf4AIMAIAQ0gDFQ=="
					}
				}
			}
		,"DEBUG":[
			{
				"<=msec": 0.000
				,"percent": 100.000
				}
			]
		}
	}

new output (valid json):

{
	"configuration":{
		"server": "localhost"
		,"port": 6379
		,"unix socket": null
		,"address family": "Unspecified"
		,"protocol": "redis"
		,"out_file": null
		,"tls": "false"
		,"cert": null
		,"key": null
		,"cacert": null
		,"tls_skip_verify": "false"
		,"sni": null
		,"client_stats": null
		,"run_count": 1
		,"debug": 0
		,"requests": 3
		,"rate_limit": 0
		,"clients": 1
		,"threads": 1
		,"test_time": 0
		,"ratio": "1:10"
		,"pipeline": 1
		,"data_size": 32
		,"data_offset": 0
		,"random_data": "false"
		,"data_size_range": "0:0"
		,"data_size_list": ""
		,"data_size_pattern": "R"
		,"expiry_range": "0:0"
		,"data_import": null
		,"data_verify": "false"
		,"verify_only": "false"
		,"generate_keys": "false"
		,"key_prefix": "memtier-"
		,"key_minimum":           0
		,"key_maximum":    10000000
		,"key_pattern": "R:R"
		,"key_stddev": 0.000000
		,"key_median": 0.000000
		,"reconnect_interval": 0
		,"multi_key_get": 0
		,"authenticate": ""
		,"select-db": 0
		,"no-expiry": "false"
		,"wait-ratio": "0:0"
		,"num-slaves": "0:0"
		,"wait-timeout": "0-0"
		}
	,"run information":{
		"Threads": 1
		,"Connections per thread": 1
		,"Requests per client": 3
		,"Format version": 2
		}
	,"ALL STATS":{
		"Runtime":{
			"Start time": 1730996277188
			,"Finish time": 1730996283195
			,"Total duration": 6007
			,"Time unit": "MILLISECONDS"
			}
		,"Debugs":{
			"Count": 3
			,"Ops/sec": 0.50
			,"Hits/sec": 0.00
			,"Misses/sec": 0.00
			,"Latency": 2000.468
			,"Average Latency": 2000.468
			,"Accumulated Latency": 6001
			,"Min Latency": 1999.872
			,"Max Latency": 2000.895
			,"KB/sec": 0.02
			,"KB/sec RX/TX": 0.02
			,"KB/sec RX": 0.00
			,"KB/sec TX": 0.02
			,"Time-Serie":{
				"0":{
					"Bytes RX": 0
					,"Bytes TX": 0
					,"Count": 0
					}
				,"2":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": 2000.400
					,"Accumulated Latency": 2000
					,"Min Latency": 2000.400
					,"Max Latency": 2000.400
					,"p50.00": 2000.895
					,"p99.00": 2000.895
					,"p99.90": 2000.895
					}
				,"4":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": 2000.518
					,"Accumulated Latency": 2000
					,"Min Latency": 2000.518
					,"Max Latency": 2000.518
					,"p50.00": 2000.895
					,"p99.00": 2000.895
					,"p99.90": 2000.895
					}
				,"6":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": 2000.487
					,"Accumulated Latency": 2000
					,"Min Latency": 2000.487
					,"Max Latency": 2000.487
					,"p50.00": 2000.895
					,"p99.00": 2000.895
					,"p99.90": 2000.895
					}
				}
			,"Percentile Latencies":{
				"p50.00": 2000.895
				,"p99.00": 2000.895
				,"p99.90": 2000.895
				,"Histogram log format":{
					"Compressed Histogram": "HISTFAAAACR4nJNpmSzMwMDAwgABzFCaC0QoH3ZjsP8AETjYx8gGAFt5BQk="
					}
				}
			}
		,"Totals":{
			"Count": 3
			,"Ops/sec": 0.50
			,"Hits/sec": 0.00
			,"Misses/sec": 0.00
			,"Latency": 2000.000
			,"Average Latency": 2000.000
			,"Accumulated Latency": 6001
			,"Min Latency": 1999.872
			,"Max Latency": 2000.895
			,"KB/sec": 0.04
			,"KB/sec RX/TX": 0.04
			,"KB/sec RX": 0.02
			,"KB/sec TX": 0.02
			,"Time-Serie":{
				"0":{
					"Bytes RX": 0
					,"Bytes TX": 0
					,"Count": 0
					}
				,"2":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": 2000.400
					,"Accumulated Latency": 2000
					,"Min Latency": 2000.400
					,"Max Latency": 2000.400
					,"p50.00": 2000.895
					,"p99.00": 2000.895
					,"p99.90": 2000.895
					}
				,"4":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": 2000.518
					,"Accumulated Latency": 2000
					,"Min Latency": 2000.518
					,"Max Latency": 2000.518
					,"p50.00": 2000.895
					,"p99.00": 2000.895
					,"p99.90": 2000.895
					}
				,"6":{
					"Bytes RX": 5
					,"Bytes TX": 33
					,"Count": 1
					,"Average Latency": 2000.487
					,"Accumulated Latency": 2000
					,"Min Latency": 2000.487
					,"Max Latency": 2000.487
					,"p50.00": 2000.895
					,"p99.00": 2000.895
					,"p99.90": 2000.895
					}
				}
			,"Percentile Latencies":{
				"p50.00": 2000.895
				,"p99.00": 2000.895
				,"p99.90": 2000.895
				,"Histogram log format":{
					"Compressed Histogram": "HISTFAAAACR4nJNpmSzMwMDAwgABzFCaC0QoH3ZjsP8AETjYx8gGAFt5BQk="
					}
				}
			}
		,"DEBUG":[
			{
				"<=msec": 2000.895
				,"percent": 0.000
				}
			,{
				"<=msec": 2000.895
				,"percent": 100.000
				}
			]
		}
	}

…cy tracking value. recording min/max outside of hdr_histogram to avoid caps. increased per second rotated histogram precision

codecov · 2024-11-07T17:41:26Z

Codecov Report

Attention: Patch coverage is 70.32967% with 27 lines in your changes missing coverage. Please review.

Project coverage is 65.26%. Comparing base (104ed9f) to head (bfe511c).
Report is 10 commits behind head on master.

Files with missing lines	Patch %	Lines
run_stats.cpp	54.38%	26 Missing ⚠️
JSON_handler.cpp	94.11%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master     #273      +/-   ##
==========================================
+ Coverage   64.53%   65.26%   +0.72%     
==========================================
  Files          21       21              
  Lines        4368     4445      +77     
==========================================
+ Hits         2819     2901      +82     
+ Misses       1549     1544       -5

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

DrEsteban · 2024-11-11T09:16:06Z

run_stats.cpp

        // to be retrocompatible
        jsonhandler->write_obj("Latency","%.3f", avg_latency);
        jsonhandler->write_obj("Average Latency","%.3f", avg_latency);
+        jsonhandler->write_obj("Accumulated Latency","%lld", m_total_latency / LATENCY_HDR_RESULTS_MULTIPLIER);


Is this just a sum of all command latency experienced throughout the test? Is it more-or-less equivalent to Average Latency * Ops?

DrEsteban · 2024-11-11T09:22:27Z

deps/hdr_histogram/hdr_histogram.h

@@ -110,6 +110,18 @@ size_t hdr_get_memory_size(struct hdr_histogram* h);
 */
 bool hdr_record_value(struct hdr_histogram* h, int64_t value);


Is this still being used anywhere? Can it be removed?

If not, and you're keeping it for compat purposes, should the method docs be updated to indicate it's deprecated or something?

Is this still being used anywhere?

@DrEsteban it's coming from the original repo: https://github.com/HdrHistogram/HdrHistogram_c
I believe it's best to create an issue there and document this further on the function signature.

Went ahead and did that: HdrHistogram/HdrHistogram_c#126

Please add details or clarifications as necessary.

Ensuring we produce a valid JSON in case of empty string and -nan

ae36f2b

filipecosta90 added the bug label Nov 7, 2024

filipecosta90 added 2 commits November 7, 2024 15:40

Ensuring latency tracing is capped both on smallest and largest laten…

21ede2f

…cy tracking value. recording min/max outside of hdr_histogram to avoid caps. increased per second rotated histogram precision

Added the latency test (command taking longer than 1 second) to CI

5ce4f41

filipecosta90 requested a review from YaacovHazan November 7, 2024 16:19

filipecosta90 added 2 commits November 7, 2024 17:06

Cleaned up test_valid_json_using_debug_command

de5019a

Ensuring that the per second metrics are numeric non negative

bfe511c

filipecosta90 requested a review from ushachar November 7, 2024 17:23

filipecosta90 requested a review from yossigo November 9, 2024 19:05

DrEsteban mentioned this pull request Nov 11, 2024

[Bug] Output file sometimes reports 0 for Ops/sec, latency, etc, in the Totals section (even though traffic occurred) #274

Open

DrEsteban reviewed Nov 11, 2024

View reviewed changes

DrEsteban approved these changes Nov 11, 2024

View reviewed changes

DrEsteban mentioned this pull request Nov 11, 2024

bool hdr_record_value(struct hdr_histogram* h, int64_t value) can record out of bounds values and should be capped with min & max values HdrHistogram/HdrHistogram_c#126

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Ensuring we produce a valid JSON in case of empty string and -nan #273

Ensuring we produce a valid JSON in case of empty string and -nan #273

filipecosta90 commented Nov 7, 2024 •

edited

Loading

codecov bot commented Nov 7, 2024

DrEsteban Nov 11, 2024 •

edited

Loading

DrEsteban Nov 11, 2024

filipecosta90 Nov 11, 2024

DrEsteban Nov 11, 2024 •

edited

Loading

		@@ -110,6 +110,18 @@ size_t hdr_get_memory_size(struct hdr_histogram* h);
		*/
		bool hdr_record_value(struct hdr_histogram* h, int64_t value);

Ensuring we produce a valid JSON in case of empty string and -nan #273

Are you sure you want to change the base?

Ensuring we produce a valid JSON in case of empty string and -nan #273

Conversation

filipecosta90 commented Nov 7, 2024 • edited Loading

codecov bot commented Nov 7, 2024

Codecov Report

DrEsteban Nov 11, 2024 • edited Loading

Choose a reason for hiding this comment

DrEsteban Nov 11, 2024

Choose a reason for hiding this comment

filipecosta90 Nov 11, 2024

Choose a reason for hiding this comment

DrEsteban Nov 11, 2024 • edited Loading

Choose a reason for hiding this comment

filipecosta90 commented Nov 7, 2024 •

edited

Loading

DrEsteban Nov 11, 2024 •

edited

Loading

DrEsteban Nov 11, 2024 •

edited

Loading