Request for Reviews(M): 7092905: C2: Keep track of the number of dead nodes

[Vladimir Ivanov]

Bharadwaj,

Have you updated the webrev with latest changes? I don't see some of the
previous comments being addressed.

Regarding the currently published version, I think that logging part can
be improved further.

The general question is: do you intentionally print this info into XML
compiler log? Why don't you use tty instead? All the messages will
appear on console and will be duplicated in <tty> section in XML log
anyway and you don't need to bother too much about the format.


Regarding the code:

src/share/vm/opto/compile.cpp
+   if (_log != NULL) {
+     _log->elem("node count before optimize compile_id='%d' unique='%d'
live (tracked)='%d' live(graph_walk)='%d'",
+                      compile_id(), unique(), live_nodes(),
count_live_nodes_by_graph_walk());
+   }

+   if (_log != NULL) {
+     _log->elem("node count after optimize compile_id='%d' unique='%d'
live (tracked)='%d' live(graph_walk)='%d'",
+                      compile_id(), unique(), live_nodes(),
count_live_nodes_by_graph_walk());
+   }

Why do you introduce new element? There's a tag <phase> which already
contains node count before and after each phase. You can enrich it with
live node count. Also, LogCompilation is diagnostic VM option, so it can
be used in production (by specifying -XX:+UnlockDiagnosticVMOptions), so
I would refrain from calling count_live_nodes_by_graph_walk, since I
consider it as an expensive operation.

Here's the code for <phase> section:
src/share/vm/opto/compile.cpp:
  3016 Compile::TracePhase::TracePhase(const char* name, elapsedTimer*
accumulator, bool dolog)
  3017   : TraceTime(NULL, accumulator, false NOT_PRODUCT( ||
TimeCompiler ), false)
  3018 {
  3019   if (dolog) {
  3020     C = Compile::current();
  3021     _log = C->log();
  3022   } else {
  3023     C = NULL;
  3024     _log = NULL;
  3025   }
  3026   if (_log != NULL) {
  3027     _log->begin_head("phase name='%s' nodes='%d'", name,
C->unique());
  3028     _log->stamp();
  3029     _log->end_head();
  3030   }
  3031 }
  3032
  3033 Compile::TracePhase::~TracePhase() {
  3034   if (_log != NULL) {
  3035     _log->done("phase nodes='%d'", C->unique());
  3036   }
  3037 }


src/share/vm/opto/compile.cpp
+#ifdef ASSERT
+  if (VerifyIdealNodeCount) {
+    if (! verify_live_node_count()) {
+      if (_log != NULL) {
+        _log->head("pre_opt dead node count mismatch");
+        print_missing_nodes();
+        _log->tail("pre_opt");
+      }
+    }
+  }
+#endif
...
#ifdef ASSERT
+void Compile::print_missing_nodes() {
...
+      if (_dead_node_list.test(i)) {
+        if (_log != NULL) {
+          _log->elem("node_liveness : compile_id='%d' node='%d' - in
both live and dead!",
+                     compile_id(), i);
+        }
+      }
+    }
+    else if (! _dead_node_list.test(i)) {
+      if (_log != NULL) {
+        _log->elem("node_liveness : compile_id='%d' node='%d' - neither
in live nor dead!",
+                   compile_id(), i);
+        }
+    }
There's no need to print compile_id, since all output will be placed in
corresponding compilation section (Comile::log() points to per-compiler
thread log file).

Also, it produces corrupted and redundant XML (':', '-' & '!' +
attributes "neither", "in", "live", etc). You can add attribute "msg" or
"message", but I would refactor the output of VerifyIdealNodeCount in
the following way:
	<node_count_mismatch>
		<node='%d' type='both live and dead'/>		
		<node='%d' type='neither live nor dead'/>		
		...
	</node_count_mismatch>

And I would also make node_count_mismatch "optional" (print the tag only
if there's any subnodes) by using CompileLog::set_context. Otherwise
each method compilation will have this section in the log, even when
there's no mismatched nodes and the section is empty.

Best regards,
Vladimir Ivanov

On 10/29/12 22:08, Bharadwaj Yadavalli wrote:
> 
> Thanks for your reviews, Vladimir and Christian.
> 
> On Oct 29, 2012, at 10:29 AM, Vladimir Kozlov
> <vladimir.kozlov at oracle.com> wrote:
>>> Bharadwaj,
>>>
>>> These changes look much better. Sorry, I suggested to add
>>> verify_live_node_count() method before but your current code don't
>>> need it, just use count_live_nodes_by_graph_walk().
> 
> OK. Made the necessary changes.
> 
>>> An other note: without LogCompilation verification code should
>>> produce some info on tty.
> 
> OK. We do not need to print the information about the number of unique
> nodes created, those that are live and those that are dead to the tty,
> correct? (Ref. around line 777 and line 816 in compile.cpp)
> 
> That leaves us with the message when there is a mismatch between the
> live node count arrived at by flow-graph walk and that kept track of via
> deal_node_list.
> 
> Would you suggest that I print out to tty indicating a mismatch? (Ref.
> around line 819 in compile.cpp) A mismatch may not always indicate that
> something is indeed wrong - given that some constant nodes that become
> unreachable (dead) can later become reachable, for example, due to
> final_graph_reshaping_walk(). Hence I do not count constant nodes that
> become unreachable as dead. So printing out a message on the tty might
> trigger false alarms. So, I chose to print a message in the log file only.
> 
> Please let me know if you still think that I should print this info (the
> one around line 819 in compile.cpp) to tty.
> 
> On 10/29/2012 1:56 PM, Christian Thalinger wrote:
>> We still need to adjust MaxNodeLimit.  Maybe some JRuby or Nashorn
>> benchmarks can help in getting really big methods.
> 
> I agree. However, I felt that arriving at the MaxNodeLimit might need
> some experimentation with different applications whose method
> compilations result in creation of graphs with large number of nodes. I
> do not (yet) know how the current value was arrived at. It appears to me
> that leaving the current value unchanged in light of these proposed
> changes would not adversely affect normal applications. So, I thought we
> could check in these changes and later check in a change to MaxNodeLimit
> based on a detailed experimentation. What do you think?
> 
>> src/share/vm/opto/compile.cpp:
>>
>> +     _log->elem("node count before optimize compile_id='%d'
>> unique='%d' live (tracked)='%d' live(graph_walk)='%d'",
>>
>> I think the log element name needs to have _'s so we can match it (if
>> we want to):
>>
>> +     _log->elem("node_count_before_optimize compile_id='%d'
>> unique='%d' live (tracked)='%d' live(graph_walk)='%d'",
> 
> OK. Changed.
> 
> Thanks,
> 
> Bharadwaj
>