[ovs-dev] [PATCH] dpdk: Add commands to configure log levels.

[Ilya Maximets]

Hi!

Thanks for the patch.  I think it migt be very useful to configure
log levels for parts of DPDK in runtime.

Comments inline.

Best regards, Ilya Maximets.

On 6/26/20 2:27 PM, David Marchand wrote:
> Enabling debug logs in dpdk can be a challenge to be sure of what is
> actually enabled, add commands to list and change those log levels.

Could you, please, provide some usage examples?
Maybe add some documentation about these commands.  And a NEWS update
since this is a user visible change.

> This does not help when tracking issues in dpdk init itself: dump log
> levels right after init.
> 
> Signed-off-by: David Marchand <david.marchand at redhat.com>
> ---
>  lib/dpdk.c | 113 +++++++++++++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 113 insertions(+)
> 
> diff --git a/lib/dpdk.c b/lib/dpdk.c
> index 31450d4708..98d0e2643e 100644
> --- a/lib/dpdk.c
> +++ b/lib/dpdk.c
> @@ -36,6 +36,7 @@
>  #include "ovs-numa.h"
>  #include "smap.h"
>  #include "svec.h"
> +#include "unixctl.h"
>  #include "util.h"
>  #include "vswitch-idl.h"
>  
> @@ -261,6 +262,102 @@ static cookie_io_functions_t dpdk_log_func = {
>      .write = dpdk_log_write,
>  };
>  
> +static void
> +dpdk_unixctl_log_list(struct unixctl_conn *conn, int argc OVS_UNUSED,
> +                      const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED)
> +{
> +    char *response = NULL;
> +    FILE *stream;
> +    size_t size;
> +
> +    stream = open_memstream(&response, &size);
> +    if (!stream) {
> +        response = xasprintf("Unable to open memstream: %s.",
> +                             ovs_strerror(errno));
> +        unixctl_command_reply_error(conn, response);
> +        goto out;
> +    }
> +
> +    rte_log_dump(stream);

This function is fine, however, I see that you're adding almost same function
do dump lcores in a later patch.  Maybe we could rename this one to
'dpdk_unixctl_memstream' and pass 'rte_log_dump' function pointer via 'aux'
argument.  This will allow us to easily add this kind of unixctl calls.

> +    fclose(stream);
> +    unixctl_command_reply(conn, response);
> +out:
> +    free(response);
> +}
> +
> +static int
> +dpdk_parse_log_level(const char *s)
> +{
> +    static const char * const levels[] = {
> +        [RTE_LOG_EMERG]   = "emergency",
> +        [RTE_LOG_ALERT]   = "alert",
> +        [RTE_LOG_CRIT]    = "critical",
> +        [RTE_LOG_ERR]     = "error",
> +        [RTE_LOG_WARNING] = "warning",
> +        [RTE_LOG_NOTICE]  = "notice",
> +        [RTE_LOG_INFO]    = "info",
> +        [RTE_LOG_DEBUG]   = "debug",
> +    };
> +    int i;
> +
> +    for (i = 1; i < ARRAY_SIZE(levels); ++i) {
> +        if (!strcmp(s, levels[i])) {
> +            return i;
> +        }
> +    }
> +    return -1;
> +}
> +
> +static void
> +dpdk_unixctl_log_set(struct unixctl_conn *conn, int argc, const char *argv[],
> +                     void *aux OVS_UNUSED)
> +{
> +    int i;
> +
> +    /* With no argument, set all logtypes level to "debug". */

Please, use single quotes if possible.

> +    if (argc == 1) {
> +        rte_log_set_level_pattern("*", RTE_LOG_DEBUG);
> +    }
> +    for (i = 1; i < argc; i++) {
> +        char *level_string;
> +        char *pattern;
> +        char *s;
> +        int level;
> +
> +        s = xstrdup(argv[i]);
> +        level_string = strchr(s, ':');
> +        if (level_string == NULL) {
> +            pattern = "*";
> +            level_string = s;
> +        } else {
> +            pattern = s;
> +            level_string[0] = '\0';
> +            level_string++;
> +        }
> +
> +        level = dpdk_parse_log_level(level_string);
> +        if (level == -1) {
> +            char *msg = xstrdup("invalid level");

Maybe it's good to print this invalid level too.

> +
> +            unixctl_command_reply_error(conn, msg);
> +            free(s);
> +            free(msg);
> +            return;
> +        }
> +
> +        if (rte_log_set_level_pattern(pattern, level) < 0) {
> +            char *msg = xasprintf("cannot set log level for %s", argv[i]);
> +
> +            unixctl_command_reply_error(conn, msg);
> +            free(s);
> +            free(msg);
> +            return;

This 4 lines repeated twice.  Maybe combine them somehow?
Something like this:

    char *err_msg = NULL;
    ...
    if (level == -1) {
        err_msg = xasprintf("invalid log level: \'%s\'", level_string);
    } else if (rte_log_set_level_pattern(pattern, level) < 0) {
        err_msg = xasprintf("cannot set log level for %s", argv[i]);
    }

    if (err_msg) {
        unixctl_command_reply_error(conn, msg);
        free(s);
        free(msg);
        return;
    }

> +        }
> +        free(s);
> +    }
> +    unixctl_command_reply(conn, NULL);
> +}
> +
>  static bool
>  dpdk_init__(const struct smap *ovs_other_config)
>  {
> @@ -423,8 +520,24 @@ dpdk_init__(const struct smap *ovs_other_config)
>              VLOG_DBG("Could not dump memzone. Unable to open memstream: %s.",
>                       ovs_strerror(errno));
>          }
> +
> +        stream = open_memstream(&response, &size);

Can we use same memstrem for both memzones and log levels to avoid code
duplication?  The error log message could say:
"Could not dump memzone and log levels. ...".

I guess, it could be:

    fwrite(steam, "rte_memzone_dump:\n");
    rte_memzone_dump(stream);
    fwrite(steam, "rte_log_dump:\n");
    rte_log_dump(stream);
    fclose(stream);
    VLOG_DBG("%s", response);
    free(response);

> +        if (stream) {
> +            rte_log_dump(stream);
> +            fclose(stream);
> +            VLOG_DBG("rte_log_dump:\n%s", response);
> +            free(response);
> +        } else {
> +            VLOG_DBG("Could not dump log levels. "
> +                     "Unable to open memstream: %s.", ovs_strerror(errno));
> +        }
>      }
>  
> +    unixctl_command_register("dpdk/log-list", "", 0, 0,
> +                             dpdk_unixctl_log_list, NULL);
> +    unixctl_command_register("dpdk/log-set", "pattern:level", 0, INT_MAX,
> +                             dpdk_unixctl_log_set, NULL);
> +
>      /* We are called from the main thread here */
>      RTE_PER_LCORE(_lcore_id) = NON_PMD_CORE_ID;
>  
>