add debug log for jvm target compile time ; fix execution graph displ…

…ay (pantsbuild#7873)

### Problem

We print out lots of relevant information to zinc/rsc compile performance with `-ldebug`, including a drawing of the execution graph, and the timings of any v2 process executions. We write per-target compile data to the run tracker which can be queried afterwards, but it would be nice to have that information written to the terminal for interactive or hacky screen-scraping use cases.

### Solution

- Write a debug log of the per-target compile data in `self._record_target_stats()`.
- Flip the direction of the `ExecutionGraph` arrows.

### Result

The debug logging during an rsc compile should hopefully be more useful!

src/python/pants/backend/jvm/tasks/jvm_compile/execution_graph.py

@@ -184,9 +184,9 @@ def format_dependee_graph(self):
     def entry(key):
       dependees = self._dependees[key]
       if dependees:
-        return "{} -> {{\n  {}\n}}".format(key, ',\n  '.join(dependees))
+        return "{} <- {{\n  {}\n}}".format(key, ',\n  '.join(dependees))
       else:
-        return "{} -> {{}}".format(key)
+        return "{} <- {{}}".format(key)
     return "\n".join([
       entry(key)
       for key in self._job_keys_as_scheduled

src/python/pants/backend/jvm/tasks/jvm_compile/jvm_compile.py

@@ -792,6 +792,9 @@ def _record_target_stats(self, target, classpath_len, sources_len, compiletime,
     # that, though (as well as the source files?).
     def record(k, v):
       self.context.run_tracker.report_target_info(self.options_scope, target, [stats_key, k], v)
+    self.context.log.debug(
+      '[Timing({})] {}: {} sec; {} sources; {} classpath elements'
+      .format(stats_key, target.address.spec, compiletime, sources_len, classpath_len))
     record('time', compiletime)
     record('classpath_len', classpath_len)
     record('sources_len', sources_len)

src/python/pants/backend/jvm/tasks/jvm_compile/rsc/rsc_compile.py

@@ -626,6 +626,8 @@ def _runtool_hermetic(self, main, tool_name, distribution, input_digest, ctx):
     if res.exit_code != 0:
       raise TaskError(res.stderr, exit_code=res.exit_code)
 
+    # TODO: parse the output of -Xprint:timings for rsc and write it to self._record_target_stats()!
+
     res.output_directory_digest.dump(ctx.rsc_jar_file.path)
 
     ctx.rsc_jar_file = ClasspathEntry(ctx.rsc_jar_file.path, res.output_directory_digest)

tests/python/pants_test/backend/jvm/tasks/jvm_compile/rsc/test_rsc_compile.py

@@ -76,8 +76,8 @@ def test_force_compiler_tags(self):
       dependee_graph = self.construct_dependee_graph_str(jobs, task)
       print(dependee_graph)
       self.assertEqual(dedent("""
-                     zinc[zinc-java](java/classpath:java_lib) -> {}
-                     zinc[zinc-only](scala/classpath:scala_lib) -> {}""").strip(),
+                     zinc[zinc-java](java/classpath:java_lib) <- {}
+                     zinc[zinc-only](scala/classpath:scala_lib) <- {}""").strip(),
         dependee_graph)
 
   def test_no_dependencies_between_scala_and_java_targets(self):
@@ -112,9 +112,9 @@ def test_no_dependencies_between_scala_and_java_targets(self):
       dependee_graph = self.construct_dependee_graph_str(jobs, task)
       print(dependee_graph)
       self.assertEqual(dedent("""
-                     zinc[zinc-java](java/classpath:java_lib) -> {}
-                     rsc(scala/classpath:scala_lib) -> {}
-                     zinc[rsc-and-zinc](scala/classpath:scala_lib) -> {}""").strip(),
+                     zinc[zinc-java](java/classpath:java_lib) <- {}
+                     rsc(scala/classpath:scala_lib) <- {}
+                     zinc[rsc-and-zinc](scala/classpath:scala_lib) <- {}""").strip(),
         dependee_graph)
 
   def test_default_workflow_of_zinc_only_zincs_scala(self):
@@ -143,7 +143,7 @@ def test_default_workflow_of_zinc_only_zincs_scala(self):
       dependee_graph = self.construct_dependee_graph_str(jobs, task)
       print(dependee_graph)
       self.assertEqual(dedent("""
-                    zinc[zinc-only](scala/classpath:scala_lib) -> {}""").strip(),
+                    zinc[zinc-only](scala/classpath:scala_lib) <- {}""").strip(),
         dependee_graph)
 
   def test_rsc_dep_for_scala_java_and_test_targets(self):
@@ -195,20 +195,20 @@ def test_rsc_dep_for_scala_java_and_test_targets(self):
       dependee_graph = self.construct_dependee_graph_str(jobs, task)
 
       self.assertEqual(dedent("""
-                     zinc[zinc-java](java/classpath:java_lib) -> {}
-                     rsc(scala/classpath:scala_lib) -> {
+                     zinc[zinc-java](java/classpath:java_lib) <- {}
+                     rsc(scala/classpath:scala_lib) <- {
                        zinc[zinc-only](scala/classpath:scala_test)
                      }
-                     zinc[rsc-and-zinc](scala/classpath:scala_lib) -> {}
-                     rsc(scala/classpath:scala_dep) -> {
+                     zinc[rsc-and-zinc](scala/classpath:scala_lib) <- {}
+                     rsc(scala/classpath:scala_dep) <- {
                        rsc(scala/classpath:scala_lib),
                        zinc[rsc-and-zinc](scala/classpath:scala_lib),
                        zinc[zinc-only](scala/classpath:scala_test)
                      }
-                     zinc[rsc-and-zinc](scala/classpath:scala_dep) -> {
+                     zinc[rsc-and-zinc](scala/classpath:scala_dep) <- {
                        zinc[zinc-java](java/classpath:java_lib)
                      }
-                     zinc[zinc-only](scala/classpath:scala_test) -> {}""").strip(),
+                     zinc[zinc-only](scala/classpath:scala_test) <- {}""").strip(),
         dependee_graph)
 
   def test_scala_lib_with_java_sources_not_passed_to_rsc(self):
@@ -252,9 +252,9 @@ def test_scala_lib_with_java_sources_not_passed_to_rsc(self):
       dependee_graph = self.construct_dependee_graph_str(jobs, task)
 
       self.assertEqual(dedent("""
-                     zinc[zinc-java](java/classpath:java_lib) -> {}
-                     zinc[zinc-java](scala/classpath:scala_with_direct_java_sources) -> {}
-                     zinc[zinc-java](scala/classpath:scala_with_indirect_java_sources) -> {}""").strip(),
+                     zinc[zinc-java](java/classpath:java_lib) <- {}
+                     zinc[zinc-java](scala/classpath:scala_with_direct_java_sources) <- {}
+                     zinc[zinc-java](scala/classpath:scala_with_indirect_java_sources) <- {}""").strip(),
         dependee_graph)
 
   def test_desandbox_fn(self):