Merge branch 'master' into stream_ctx

src/core/profiling/basic_timers.c

@@ -45,7 +45,12 @@
 #include <grpc/support/thd.h>
 #include <stdio.h>
 
-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);

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);
 };

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);
 }

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__); \

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

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, '<a href="$log_link/$log_file_name">log</a>']," >> /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, '<a href="$log_link/$log_file_name">log</a>']," >> /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, '<a href="$log_link/$log_file_name">log</a>']," >> /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, '<a href="$log_link/$log_file_name">log</a>']," >> /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

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:

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, '<a href="$log_link/$log_file_name">log</a>']," >> /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, '<a href="$log_link/$log_file_name">log</a>']," >> /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

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