From bd061ecf47e82e6ad119ab5e38ed583ec7d2d18a Mon Sep 17 00:00:00 2001 From: Stanley Cheung Date: Thu, 4 Jun 2020 13:14:25 -0700 Subject: [PATCH 1/2] Add debug info to xds test --- src/php/tests/interop/xds_client.php | 15 ++++++++++----- src/ruby/pb/test/xds_client.rb | 10 +++++++--- 2 files changed, 17 insertions(+), 8 deletions(-) diff --git a/src/php/tests/interop/xds_client.php b/src/php/tests/interop/xds_client.php index 661760f2bcf..0f92c6de7bd 100644 --- a/src/php/tests/interop/xds_client.php +++ b/src/php/tests/interop/xds_client.php @@ -103,18 +103,23 @@ class ClientThread extends Thread { 'credentials' => Grpc\ChannelCredentials::createInsecure() ]); $request = new Grpc\Testing\SimpleRequest(); - $target_next_start_us = hrtime(true) / 1000; + $target_next_start_us = hrtime(true) / 1000; # hrtime returns nanoseconds while (true) { $now_us = hrtime(true) / 1000; $sleep_us = $target_next_start_us - $now_us; if ($sleep_us < 0) { - echo "php xds: warning, rpc takes too long to finish. " - . "If you consistently see this, the qps is too high.\n"; + $target_next_start_us = + $now_us + ($this->target_seconds_between_rpcs_ * 1e6); + echo sprintf( + "php xds: warning, rpc takes too long to finish. " + . "Deficit %fms." + . "If you consistently see this, the qps is too high.\n", + round(abs($sleep_us / 1000), 1)); } else { + $target_next_start_us += + ($this->target_seconds_between_rpcs_ * 1e6); usleep($sleep_us); } - $target_next_start_us - += ($this->target_seconds_between_rpcs_ * 1000000); list($response, $status) = $stub->UnaryCall($request)->wait(); if ($status->code == Grpc\STATUS_OK) { diff --git a/src/ruby/pb/test/xds_client.rb b/src/ruby/pb/test/xds_client.rb index 4ca5850b4bb..e53a1a4e0e4 100755 --- a/src/ruby/pb/test/xds_client.rb +++ b/src/ruby/pb/test/xds_client.rb @@ -111,12 +111,16 @@ def run_test_loop(stub, target_seconds_between_rpcs, fail_on_failed_rpcs) now = Process.clock_gettime(Process::CLOCK_MONOTONIC) sleep_seconds = target_next_start - now if sleep_seconds < 0 - GRPC.logger.info("ruby xds: warning, rpc takes too long to finish. " \ - "If you consistently see this, the qps is too high.") + target_next_start = now + target_seconds_between_rpcs + GRPC.logger.info( + "ruby xds: warning, rpc takes too long to finish. " \ + "Deficit = %fms. " \ + "If you consistently see this, the qps is too high." + % [(sleep_seconds * 1000).abs().round(1)]) else + target_next_start += target_seconds_between_rpcs sleep(sleep_seconds) end - target_next_start += target_seconds_between_rpcs begin resp = stub.unary_call(req) remote_peer = resp.hostname From 503e2f8766ca9ae310f574d7c14586668a87bc89 Mon Sep 17 00:00:00 2001 From: Stanley Cheung Date: Thu, 4 Jun 2020 20:44:17 +0000 Subject: [PATCH 2/2] Fix format --- src/php/tests/interop/xds_client.php | 2 +- src/ruby/pb/test/xds_client.rb | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/php/tests/interop/xds_client.php b/src/php/tests/interop/xds_client.php index 0f92c6de7bd..a44287e4c92 100644 --- a/src/php/tests/interop/xds_client.php +++ b/src/php/tests/interop/xds_client.php @@ -112,7 +112,7 @@ class ClientThread extends Thread { $now_us + ($this->target_seconds_between_rpcs_ * 1e6); echo sprintf( "php xds: warning, rpc takes too long to finish. " - . "Deficit %fms." + . "Deficit %.1fms." . "If you consistently see this, the qps is too high.\n", round(abs($sleep_us / 1000), 1)); } else { diff --git a/src/ruby/pb/test/xds_client.rb b/src/ruby/pb/test/xds_client.rb index e53a1a4e0e4..4310a87f2ed 100755 --- a/src/ruby/pb/test/xds_client.rb +++ b/src/ruby/pb/test/xds_client.rb @@ -114,8 +114,8 @@ def run_test_loop(stub, target_seconds_between_rpcs, fail_on_failed_rpcs) target_next_start = now + target_seconds_between_rpcs GRPC.logger.info( "ruby xds: warning, rpc takes too long to finish. " \ - "Deficit = %fms. " \ - "If you consistently see this, the qps is too high." + "Deficit = %.1fms. " \ + "If you consistently see this, the qps is too high." \ % [(sleep_seconds * 1000).abs().round(1)]) else target_next_start += target_seconds_between_rpcs