From ab4ad8590b45db6ad6dd96ef954e7e33861c712c Mon Sep 17 00:00:00 2001 From: Stanley Cheung Date: Tue, 5 May 2015 14:46:23 -0700 Subject: [PATCH 1/5] add command for the rest of PHP interop test --- tools/gce_setup/grpc_docker.sh | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/tools/gce_setup/grpc_docker.sh b/tools/gce_setup/grpc_docker.sh index ecce0e29834..d3a7bdef285 100755 --- a/tools/gce_setup/grpc_docker.sh +++ b/tools/gce_setup/grpc_docker.sh @@ -1250,6 +1250,20 @@ grpc_interop_gen_php_cmd() { echo $the_cmd } +# constructs the full dockerized php gce=>prod interop test cmd. +# +# call-seq: +# flags= .... # generic flags to include the command +# cmd=$($grpc_gen_test_cmd $flags) +grpc_cloud_prod_gen_php_cmd() { + local env_flag="-e SSL_CERT_FILE=/cacerts/roots.pem " + local cmd_prefix="sudo docker run $env_flag grpc/php"; + local test_script="/var/local/git/grpc/src/php/bin/interop_client.sh"; + local gfe_flags=$(_grpc_prod_gfe_flags); + local the_cmd="$cmd_prefix $test_script $gfe_flags $@"; + echo $the_cmd +} + # constructs the full dockerized php service_account auth interop test cmd. # # call-seq: From 73423ae76d1ffcec73af4a504aaac6884f3df49e Mon Sep 17 00:00:00 2001 From: David Garcia Quintas Date: Tue, 5 May 2015 17:11:04 -0700 Subject: [PATCH 2/5] Added important (!) profiling mark. It's meant to have a special status in the analysis, whereby latencies from important marks to all their enclosing BEGIN ({) and END (}) markings will be measured. --- src/core/profiling/basic_timers.c | 14 +++++++++++++- src/core/profiling/stap_probes.d | 1 + src/core/profiling/stap_timers.c | 5 +++++ src/core/profiling/timers.h | 12 ++++++++++++ 4 files changed, 31 insertions(+), 1 deletion(-) diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c index 866833f2257..124a8d6621a 100644 --- a/src/core/profiling/basic_timers.c +++ b/src/core/profiling/basic_timers.c @@ -45,7 +45,12 @@ #include #include -typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type; +typedef enum { + BEGIN = '{', + END = '}', + MARK = '.', + IMPORTANT = '!' +} marker_type; typedef struct grpc_timer_entry { grpc_precise_clock tm; @@ -101,6 +106,13 @@ void grpc_timer_add_mark(int tag, void* id, const char* file, int line) { } } +void grpc_timer_add_important_mark(int tag, void* id, const char* file, + int line) { + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { + grpc_timers_log_add(tag, IMPORTANT, id, file, line); + } +} + void grpc_timer_begin(int tag, void* id, const char* file, int line) { if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { grpc_timers_log_add(tag, BEGIN, id, file, line); diff --git a/src/core/profiling/stap_probes.d b/src/core/profiling/stap_probes.d index 374eeedd6c0..153de91752a 100644 --- a/src/core/profiling/stap_probes.d +++ b/src/core/profiling/stap_probes.d @@ -1,5 +1,6 @@ provider _stap { probe add_mark(int tag); + probe add_important_mark(int tag); probe timing_ns_begin(int tag); probe timing_ns_end(int tag); }; diff --git a/src/core/profiling/stap_timers.c b/src/core/profiling/stap_timers.c index 6e3a965dae9..064c86e794e 100644 --- a/src/core/profiling/stap_timers.c +++ b/src/core/profiling/stap_timers.c @@ -46,6 +46,11 @@ void grpc_timer_add_mark(int tag, void* id, const char* file, int line) { _STAP_ADD_MARK(tag); } +void grpc_timer_add_important_mark(int tag, void* id, const char* file, + int line) { + _STAP_ADD_IMPORTANT_MARK(tag); +} + void grpc_timer_begin(int tag, void* id, const char* file, int line) { _STAP_TIMING_NS_BEGIN(tag); } diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h index 0b0f7152e79..4fb465c2371 100644 --- a/src/core/profiling/timers.h +++ b/src/core/profiling/timers.h @@ -42,6 +42,8 @@ void grpc_timers_global_init(void); void grpc_timers_global_destroy(void); void grpc_timer_add_mark(int tag, void *id, const char *file, int line); +void grpc_timer_add_important_mark(int tag, void *id, const char *file, + int line); void grpc_timer_begin(int tag, void *id, const char *file, int line); void grpc_timer_end(int tag, void *id, const char *file, int line); @@ -82,6 +84,10 @@ enum grpc_profiling_tags { do { \ } while (0) +#define GRPC_TIMER_IMPORTANT_MARK(tag, id) \ + do { \ + } while (0) + #define GRPC_TIMER_BEGIN(tag, id) \ do { \ } while (0) @@ -102,6 +108,12 @@ enum grpc_profiling_tags { grpc_timer_add_mark(tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \ } +#define GRPC_TIMER_IMPORTANT_MARK(tag, id) \ + if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ + grpc_timer_add_important_mark(tag, ((void *)(gpr_intptr)(id)), __FILE__, \ + __LINE__); \ + } + #define GRPC_TIMER_BEGIN(tag, id) \ if (tag < GRPC_PTAG_IGNORE_THRESHOLD) { \ grpc_timer_begin(tag, ((void *)(gpr_intptr)(id)), __FILE__, __LINE__); \ From 5b2ea2979b9fe27cf50d60325ad8a3ae26d46cf6 Mon Sep 17 00:00:00 2001 From: David Garcia Quintas Date: Wed, 6 May 2015 09:57:49 -0700 Subject: [PATCH 3/5] Added support for important mark (!) analysis. For example, an input of GRPC_LAT_PROF 1316908107613.015869 0x7fd35f7fe700 { 205 (nil) src/core/iomgr/tcp_posix.c 1 GRPC_LAT_PROF 1316908107614.015869 0x7fd35f7fe700 { 205 (nil) src/core/iomgr/tcp_posix.c 2 GRPC_LAT_PROF 1316908107615.015869 0x7fd35f7fe700 ! 999999 (nil) src/core/iomgr/tcp_posix.c 3 GRPC_LAT_PROF 1316908107616.015869 0x7fd35f7fe700 } 205 (nil) src/core/iomgr/tcp_posix.c 4 GRPC_LAT_PROF 1316908107617.015869 0x7fd35f7fe700 ! 999999 (nil) src/core/iomgr/tcp_posix.c 5 GRPC_LAT_PROF 1316908107618.015869 0x7fd35f7fe700 } 205 (nil) src/core/iomgr/tcp_posix.c 6 results in tag 50%/90%/95%/99% us 205 5.00/5.00/5.00/5.00 Important marks: ================ 999999 @ src/core/iomgr/tcp_posix.c:3 205 { (src/core/iomgr/tcp_posix.c:1): 2.000 us 205 { (src/core/iomgr/tcp_posix.c:2): 1.000 us 205 } (src/core/iomgr/tcp_posix.c:4): -1.000 us 205 } (src/core/iomgr/tcp_posix.c:6): -3.000 us 999999 @ src/core/iomgr/tcp_posix.c:5 205 { (src/core/iomgr/tcp_posix.c:1): 4.000 us 205 } (src/core/iomgr/tcp_posix.c:6): -1.000 us --- tools/profile_analyzer/profile_analyzer.py | 56 +++++++++++++++++++++- 1 file changed, 54 insertions(+), 2 deletions(-) diff --git a/tools/profile_analyzer/profile_analyzer.py b/tools/profile_analyzer/profile_analyzer.py index f15277491fe..00b10794668 100755 --- a/tools/profile_analyzer/profile_analyzer.py +++ b/tools/profile_analyzer/profile_analyzer.py @@ -38,19 +38,43 @@ Usage: import collections +import itertools import re import sys # Create a regex to parse output of the C core basic profiler, # as defined in src/core/profiling/basic_timers.c. _RE_LINE = re.compile(r'GRPC_LAT_PROF ' + - r'([0-9]+\.[0-9]+) 0x([0-9a-f]+) ([{}.]) ([0-9]+) ' + + r'([0-9]+\.[0-9]+) 0x([0-9a-f]+) ([{}.!]) ([0-9]+) ' + r'([^ ]+) ([^ ]+) ([0-9]+)') Entry = collections.namedtuple( 'Entry', ['time', 'thread', 'type', 'tag', 'id', 'file', 'line']) + +class ImportantMark(object): + def __init__(self, entry, stack): + self._entry = entry + self._pre_stack = stack + self._post_stack = list() + self._n = len(stack) # we'll also compute times to that many closing }s + + @property + def entry(self): + return self._entry + + def append_post_entry(self, entry): + if self._n > 0: + self._post_stack.append(entry) + self._n -= 1 + + def get_deltas(self): + pre_and_post_stacks = itertools.chain(self._pre_stack, self._post_stack) + return collections.OrderedDict((stack_entry, + (self._entry.time - stack_entry.time)) + for stack_entry in pre_and_post_stacks) + def entries(): for line in sys.stdin: m = _RE_LINE.match(line) @@ -66,13 +90,27 @@ def entries(): threads = collections.defaultdict(lambda: collections.defaultdict(list)) times = collections.defaultdict(list) +# Indexed by the mark's tag. Items in the value list correspond to the mark in +# different stack situations. +important_marks = collections.defaultdict(list) + for entry in entries(): thread = threads[entry.thread] if entry.type == '{': thread[entry.tag].append(entry) + if entry.type == '!': + # Save a snapshot of the current stack inside a new ImportantMark instance. + # Get all entries with type '{' from "thread". + stack = [e for entries_for_tag in thread.values() + for e in entries_for_tag if e.type == '{'] + important_marks[entry.tag].append(ImportantMark(entry, stack)) elif entry.type == '}': last = thread[entry.tag].pop() times[entry.tag].append(entry.time - last.time) + # Update accounting for important marks. + for imarks_for_tag in important_marks.itervalues(): + for imark in imarks_for_tag: + imark.append_post_entry(entry) def percentile(vals, pct): return sorted(vals)[int(len(vals) * pct / 100.0)] @@ -80,8 +118,22 @@ def percentile(vals, pct): print 'tag 50%/90%/95%/99% us' for tag in sorted(times.keys()): vals = times[tag] - print '%d %.2f/%.2f/%.2f/%.2f' % (tag, + print '%d %.2f/%.2f/%.2f/%.2f' % (tag, percentile(vals, 50), percentile(vals, 90), percentile(vals, 95), percentile(vals, 99)) + +print +print 'Important marks:' +print '================' +for tag, imark_for_tag in important_marks.iteritems(): + for imark in imarks_for_tag: + deltas = imark.get_deltas() + print '{tag} @ {file}:{line}'.format(**imark.entry._asdict()) + for entry, time_delta_us in deltas.iteritems(): + format_dict = entry._asdict() + format_dict['time_delta_us'] = time_delta_us + print '{tag} {type} ({file}:{line}): {time_delta_us:12.3f} us'.format( + **format_dict) + print From f2fb07dafc5ef88a6fcd5c4f98c75ffa7f7a3f72 Mon Sep 17 00:00:00 2001 From: Tim Emiola Date: Wed, 6 May 2015 10:22:35 -0700 Subject: [PATCH 4/5] Pin the version of rubocop used in grpc.gemspec --- src/ruby/grpc.gemspec | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/ruby/grpc.gemspec b/src/ruby/grpc.gemspec index 19b3e21cb6d..3ddb7fac18f 100755 --- a/src/ruby/grpc.gemspec +++ b/src/ruby/grpc.gemspec @@ -34,7 +34,7 @@ Gem::Specification.new do |s| s.add_development_dependency 'rake', '~> 10.4' s.add_development_dependency 'rake-compiler', '~> 0.9' s.add_development_dependency 'rspec', '~> 3.2' - s.add_development_dependency 'rubocop', '~> 0.30' + s.add_development_dependency 'rubocop', '~> 0.30.0' s.extensions = %w(ext/grpc/extconf.rb) end From 5c1368e20050b56822ccdc9e4bc77aecd50caf1d Mon Sep 17 00:00:00 2001 From: Donna Dionne Date: Wed, 6 May 2015 13:19:20 -0700 Subject: [PATCH 5/5] Ensuring test logs are not over written between runs. --- tools/gce_setup/cloud_prod_runner.sh | 11 ++++++----- tools/gce_setup/interop_test_runner.sh | 7 ++++--- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/tools/gce_setup/cloud_prod_runner.sh b/tools/gce_setup/cloud_prod_runner.sh index 812be4061cd..5f3b61eb52b 100755 --- a/tools/gce_setup/cloud_prod_runner.sh +++ b/tools/gce_setup/cloud_prod_runner.sh @@ -32,7 +32,7 @@ thisfile=$(readlink -ne "${BASH_SOURCE[0]}") current_time=$(date "+%Y-%m-%d-%H-%M-%S") result_file_name=cloud_prod_result.$current_time.html echo $result_file_name -log_link=https://pantheon.corp.google.com/m/cloudstorage/b/stoked-keyword-656-output/o/log_history +log_link=https://pantheon.corp.google.com/m/cloudstorage/b/stoked-keyword-656-output/o/log/cloud_prod_log_history main() { source grpc_docker.sh @@ -46,10 +46,10 @@ main() { log_file_name=cloud_{$test_case}_{$client}.txt if grpc_cloud_prod_test $test_case grpc-docker-testclients $client > /tmp/$log_file_name 2>&1 then - gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/log_history/$log_file_name + gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/cloud_prod_log_history/$log_file_name echo " ['$test_case', '$client', 'prod', true, 'log']," >> /tmp/cloud_prod_result.txt else - gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/log_history/$log_file_name + gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/cloud_prod_log_history/$log_file_name echo " ['$test_case', '$client', 'prod', false, 'log']," >> /tmp/cloud_prod_result.txt fi done @@ -61,10 +61,10 @@ main() { log_file_name=cloud_{$test_case}_{$client}.txt if grpc_cloud_prod_auth_test $test_case grpc-docker-testclients $client > /tmp/$log_file_name 2>&1 then - gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/log_history/$log_file_name + gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/cloud_prod_log_history/$log_file_name echo " ['$test_case', '$client', 'prod', true, 'log']," >> /tmp/cloud_prod_result.txt else - gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/log_history/$log_file_name + gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/cloud_prod_log_history/$log_file_name echo " ['$test_case', '$client', 'prod', false, 'log']," >> /tmp/cloud_prod_result.txt fi done @@ -72,6 +72,7 @@ main() { if [[ "${BASH_SOURCE[0]}" == "${0}" ]]; then cat pre.html /tmp/cloud_prod_result.txt post.html > /tmp/cloud_prod_result.html gsutil cp /tmp/cloud_prod_result.txt gs://stoked-keyword-656-output/cloud_prod_result.txt + gsutil cp -R gs://stoked-keyword-656-output/cloud_prod_log_history gs://stoked-keyword-656-output/log gsutil cp /tmp/cloud_prod_result.html gs://stoked-keyword-656-output/cloud_prod_result.html gsutil cp /tmp/cloud_prod_result.html gs://stoked-keyword-656-output/result_history/$result_file_name rm /tmp/cloud_prod_result.txt diff --git a/tools/gce_setup/interop_test_runner.sh b/tools/gce_setup/interop_test_runner.sh index b9f026e5452..ff3d5369300 100755 --- a/tools/gce_setup/interop_test_runner.sh +++ b/tools/gce_setup/interop_test_runner.sh @@ -32,7 +32,7 @@ thisfile=$(readlink -ne "${BASH_SOURCE[0]}") current_time=$(date "+%Y-%m-%d-%H-%M-%S") result_file_name=interop_result.$current_time.html echo $result_file_name -log_link=https://pantheon.corp.google.com/m/cloudstorage/b/stoked-keyword-656-output/o/log_history +log_link=https://pantheon.corp.google.com/m/cloudstorage/b/stoked-keyword-656-output/o/log/interop_log_history main() { source grpc_docker.sh @@ -48,10 +48,10 @@ main() { log_file_name=interop_{$test_case}_{$client}_{$server}.txt if grpc_interop_test $test_case grpc-docker-testclients $client grpc-docker-server $server > /tmp/$log_file_name 2>&1 then - gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/log_history/$log_file_name + gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/inteorp_log_history/$log_file_name echo " ['$test_case', '$client', '$server', true, 'log']," >> /tmp/interop_result.txt else - gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/log_history/$log_file_name + gsutil cp /tmp/$log_file_name gs://stoked-keyword-656-output/interop_log_history/$log_file_name echo " ['$test_case', '$client', '$server', false, 'log']," >> /tmp/interop_result.txt fi done @@ -60,6 +60,7 @@ main() { if [[ "${BASH_SOURCE[0]}" == "${0}" ]]; then cat pre.html /tmp/interop_result.txt post.html > /tmp/interop_result.html gsutil cp /tmp/interop_result.txt gs://stoked-keyword-656-output/interop_result.txt + gsutil cp -R gs://stoked-keyword-656-output/interop_log_history gs://stoked-keyword-656-output/log gsutil cp /tmp/interop_result.html gs://stoked-keyword-656-output/interop_result.html gsutil cp /tmp/interop_result.html gs://stoked-keyword-656-output/result_history/$result_file_name rm /tmp/interop_result.txt