Merge pull request #23139 from stanley-cheung/debug-php-xds-qps

Add debug to php / ruby xds test around qps param

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 %.1fms."
+                    . "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) {

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 = %.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
       sleep(sleep_seconds)
     end
-    target_next_start += target_seconds_between_rpcs
     begin
       resp = stub.unary_call(req)
       remote_peer = resp.hostname