coll/tuned: Refactor logging, and add coll_tuned_verbose mca parameter

Previously the coll_tuned output stream didn't use opal_output_set_verbosity at all. This made it difficult to distinguish problems from noisy logging. Signed-off-by: Luke Robison <lrbison@amazon.com>

Author: Luke Robison

ompi/mca/coll/tuned/coll_tuned.h

@@ -32,6 +32,8 @@
 
 BEGIN_C_DECLS
 
+#define COLL_TUNED_TRACING_VERBOSE 50
+
 /* these are the same across all modules and are loaded at component query time */
 extern int ompi_coll_tuned_stream;
 extern int ompi_coll_tuned_priority;

ompi/mca/coll/tuned/coll_tuned_allgather_decision.c

@@ -135,7 +135,7 @@ int ompi_coll_tuned_allgather_intra_do_this(const void *sbuf, size_t scount,
  mca_coll_base_module_t *module,
  int algorithm, int faninout, int segsize)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream,
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
  "coll:tuned:allgather_intra_do_this selected algorithm %d topo faninout %d segsize %d",
  algorithm, faninout, segsize));
  switch (algorithm) {
@@ -176,7 +176,7 @@ int ompi_coll_tuned_allgather_intra_do_this(const void *sbuf, size_t scount,
  rbuf, rcount, rdtype,
  comm, module);
  } /* switch */
- OPAL_OUTPUT((ompi_coll_tuned_stream,
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
  "coll:tuned:allgather_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
  algorithm, ompi_coll_tuned_forced_max_algorithms[ALLGATHER]));
  return (MPI_ERR_ARG);

ompi/mca/coll/tuned/coll_tuned_allgatherv_decision.c

@@ -135,7 +135,7 @@ int ompi_coll_tuned_allgatherv_intra_do_this(const void *sbuf, size_t scount,
  int algorithm, int faninout,
  int segsize)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream,
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
  "coll:tuned:allgatherv_intra_do_this selected algorithm %d topo faninout %d segsize %d",
  algorithm, faninout, segsize));
 
@@ -169,7 +169,7 @@ int ompi_coll_tuned_allgatherv_intra_do_this(const void *sbuf, size_t scount,
  rbuf, rcounts, rdispls, rdtype,
  comm, module);
  } /* switch */
- OPAL_OUTPUT((ompi_coll_tuned_stream,
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
  "coll:tuned:allgatherv_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
  algorithm, ompi_coll_tuned_forced_max_algorithms[ALLGATHERV]));
  return (MPI_ERR_ARG);

ompi/mca/coll/tuned/coll_tuned_allreduce_decision.c

@@ -132,8 +132,9 @@ int ompi_coll_tuned_allreduce_intra_do_this(const void *sbuf, void *rbuf, size_t
  mca_coll_base_module_t *module,
  int algorithm, int faninout, int segsize)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:allreduce_intra_do_this algorithm %d topo fan in/out %d segsize %d",
- algorithm, faninout, segsize));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:allreduce_intra_do_this algorithm %d topo fan in/out %d segsize %d",
+ algorithm, faninout, segsize));
 
  switch (algorithm) {
  case (0):
@@ -153,7 +154,8 @@ int ompi_coll_tuned_allreduce_intra_do_this(const void *sbuf, void *rbuf, size_t
  case (7):
  return ompi_coll_base_allreduce_intra_allgather_reduce(sbuf, rbuf, count, dtype, op, comm, module);
  } /* switch */
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:allreduce_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
- algorithm, ompi_coll_tuned_forced_max_algorithms[ALLREDUCE]));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:allreduce_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
+ algorithm, ompi_coll_tuned_forced_max_algorithms[ALLREDUCE]));
  return (MPI_ERR_ARG);
 }

ompi/mca/coll/tuned/coll_tuned_alltoall_decision.c

@@ -167,8 +167,9 @@ int ompi_coll_tuned_alltoall_intra_do_this(const void *sbuf, size_t scount,
  int algorithm, int faninout, int segsize,
  int max_requests)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:alltoall_intra_do_this selected algorithm %d topo faninout %d segsize %d",
- algorithm, faninout, segsize));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:alltoall_intra_do_this selected algorithm %d topo faninout %d segsize %d",
+ algorithm, faninout, segsize));
 
  switch (algorithm) {
  case (0):
@@ -184,7 +185,8 @@ int ompi_coll_tuned_alltoall_intra_do_this(const void *sbuf, size_t scount,
  case (5):
  return ompi_coll_base_alltoall_intra_two_procs(sbuf, scount, sdtype, rbuf, rcount, rdtype, comm, module);
  } /* switch */
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:alltoall_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
- algorithm, ompi_coll_tuned_forced_max_algorithms[ALLTOALL]));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:alltoall_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
+ algorithm, ompi_coll_tuned_forced_max_algorithms[ALLTOALL]));
  return (MPI_ERR_ARG);
 }

ompi/mca/coll/tuned/coll_tuned_alltoallv_decision.c

@@ -98,7 +98,7 @@ int ompi_coll_tuned_alltoallv_intra_do_this(const void *sbuf, ompi_count_array_t
  mca_coll_base_module_t *module,
  int algorithm)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream,
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
  "coll:tuned:alltoallv_intra_do_this selected algorithm %d ",
  algorithm));
 
@@ -116,7 +116,7 @@ int ompi_coll_tuned_alltoallv_intra_do_this(const void *sbuf, ompi_count_array_t
  rbuf, rcounts, rdisps, rdtype,
  comm, module);
  } /* switch */
- OPAL_OUTPUT((ompi_coll_tuned_stream,
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
  "coll:tuned:alltoall_intra_do_this attempt to select "
  "algorithm %d when only 0-%d is valid.",
  algorithm, ompi_coll_tuned_forced_max_algorithms[ALLTOALLV]));

ompi/mca/coll/tuned/coll_tuned_barrier_decision.c

@@ -93,7 +93,7 @@ int ompi_coll_tuned_barrier_intra_do_this (struct ompi_communicator_t *comm,
  mca_coll_base_module_t *module,
  int algorithm, int faninout, int segsize)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream,
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
  "coll:tuned:barrier_intra_do_this selected algorithm %d topo fanin/out%d",
  algorithm, faninout));
 
@@ -106,7 +106,8 @@ int ompi_coll_tuned_barrier_intra_do_this (struct ompi_communicator_t *comm,
  case (5): return ompi_coll_base_barrier_intra_two_procs(comm, module);
  case (6): return ompi_coll_base_barrier_intra_tree(comm, module);
  } /* switch */
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:barrier_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
- algorithm, ompi_coll_tuned_forced_max_algorithms[BARRIER]));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:barrier_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
+ algorithm, ompi_coll_tuned_forced_max_algorithms[BARRIER]));
  return (MPI_ERR_ARG);
 }

ompi/mca/coll/tuned/coll_tuned_bcast_decision.c

@@ -142,8 +142,9 @@ int ompi_coll_tuned_bcast_intra_do_this(void *buf, size_t count,
  mca_coll_base_module_t *module,
  int algorithm, int faninout, int segsize)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:bcast_intra_do_this algorithm %d topo faninout %d segsize %d",
- algorithm, faninout, segsize));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:bcast_intra_do_this algorithm %d topo faninout %d segsize %d",
+ algorithm, faninout, segsize));
 
  switch (algorithm) {
  case (0):
@@ -168,7 +169,8 @@ int ompi_coll_tuned_bcast_intra_do_this(void *buf, size_t count,
  case (9):
  return ompi_coll_base_bcast_intra_scatter_allgather_ring(buf, count, dtype, root, comm, module, segsize);
  } /* switch */
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:bcast_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
- algorithm, ompi_coll_tuned_forced_max_algorithms[BCAST]));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:bcast_intra_do_this attempt to select algorithm %d when only 0-%d is valid?",
+ algorithm, ompi_coll_tuned_forced_max_algorithms[BCAST]));
  return (MPI_ERR_ARG);
 }

ompi/mca/coll/tuned/coll_tuned_component.c

@@ -58,6 +58,7 @@ char* ompi_coll_tuned_dynamic_rules_filename = (char*) NULL;
 int ompi_coll_tuned_init_tree_fanout = 4;
 int ompi_coll_tuned_init_chain_fanout = 4;
 int ompi_coll_tuned_init_max_requests = 128;
+int ompi_coll_tuned_verbose = 0;
 
 /* Set it to the same value as intermediate msg by default, so it does not affect
  * default algorithm selection. Changing this value will force using linear with
@@ -193,6 +194,15 @@ static int tuned_register(void)
  MCA_BASE_VAR_SCOPE_ALL,
  &ompi_coll_tuned_dynamic_rules_filename);
 
+ ompi_coll_tuned_verbose = 0;
+ (void) mca_base_component_var_register(&mca_coll_tuned_component.super.collm_version,
+ "verbose",
+ "Verbosity of the tuned coll component",
+ MCA_BASE_VAR_TYPE_INT, NULL, 0, MCA_BASE_VAR_FLAG_SETTABLE,
+ OPAL_INFO_LVL_9,
+ MCA_BASE_VAR_SCOPE_ALL,
+ &ompi_coll_tuned_verbose);
+
  /* register forced params */
  ompi_coll_tuned_allreduce_intra_check_forced_init(&ompi_coll_tuned_forced_params[ALLREDUCE]);
  ompi_coll_tuned_alltoall_intra_check_forced_init(&ompi_coll_tuned_forced_params[ALLTOALL]);
@@ -216,11 +226,10 @@ static int tuned_open(void)
 {
  int rc;
 
-#if OPAL_ENABLE_DEBUG
- if (ompi_coll_base_framework.framework_verbose) {
+ if (ompi_coll_tuned_verbose) {
  ompi_coll_tuned_stream = opal_output_open(NULL);
+ opal_output_set_verbosity(ompi_coll_tuned_stream, ompi_coll_tuned_verbose);
  }
-#endif /* OPAL_ENABLE_DEBUG */
 
  /* now check that the user hasn't overrode any of the decision functions if dynamic rules are enabled */
  /* the user can redo this before every comm dup/create if they like */
@@ -233,20 +242,24 @@ static int tuned_open(void)
  /* by default DISABLE dynamic rules and instead use fixed [if based] rules */
  if (ompi_coll_tuned_use_dynamic_rules) {
  if( ompi_coll_tuned_dynamic_rules_filename ) {
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:component_open Reading collective rules file [%s]",
- ompi_coll_tuned_dynamic_rules_filename));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:component_open Reading collective rules file [%s]",
+ ompi_coll_tuned_dynamic_rules_filename));
  rc = ompi_coll_tuned_read_rules_config_file( ompi_coll_tuned_dynamic_rules_filename,
  &(mca_coll_tuned_component.all_base_rules));
  if( rc == OPAL_SUCCESS ) {
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:module_open Read a valid rules file"));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:module_open Read a valid rules file"));
  } else {
- OPAL_OUTPUT((ompi_coll_tuned_stream,"coll:tuned:module_open Reading collective rules file failed\n"));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:module_open Reading collective rules file failed\n"));
  mca_coll_tuned_component.all_base_rules = NULL;
  }
  }
  }
 
- OPAL_OUTPUT((ompi_coll_tuned_stream, "coll:tuned:component_open: done!"));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:component_open: done!"));
 
  return OMPI_SUCCESS;
 }
@@ -255,12 +268,14 @@ static int tuned_open(void)
 /* i.e. alg table and dynamic changeable rules if allocated etc */
 static int tuned_close(void)
 {
- OPAL_OUTPUT((ompi_coll_tuned_stream, "coll:tuned:component_close: called"));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:component_close: called"));
 
  /* dealloc alg table if allocated */
  /* dealloc dynamic changeable rules if allocated */
 
- OPAL_OUTPUT((ompi_coll_tuned_stream, "coll:tuned:component_close: done!"));
+ OPAL_OUTPUT_VERBOSE((COLL_TUNED_TRACING_VERBOSE, ompi_coll_tuned_stream,
+ "coll:tuned:component_close: done!"));
 
  if( NULL != mca_coll_tuned_component.all_base_rules ) {
  ompi_coll_tuned_free_all_rules(mca_coll_tuned_component.all_base_rules);