| Message ID | 20200626122723.28098-1-david.marchand@redhat.com |
|---|---|
| State | Superseded |
| Delegated to: | Ilya Maximets |
| Headers | show |
| Series | [ovs-dev] dpdk: Add commands to configure log levels. | expand |
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@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; > >
On Thu, Jul 2, 2020 at 12:05 AM Ilya Maximets <i.maximets@ovn.org> wrote: > 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. In the documentation, example outputs could get outdated since we directly pass dpdk output (/me still wants to shoot the dpdk global log level that is just useless). But I think it is still worth adding. I would see either in Documentation/howto/dpdk.rst or Documentation/intro/install/dpdk.rst. The latter seems the best fit: we have setup instructions, configuring logs is close. WDYT? [snip] > > @@ -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. dpdk "dump" apis tend to have the same prototype, so yes it will save some code. [snip] > > + > > + 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); No need for escaping? Thanks for the review.
On 7/2/20 10:25 AM, David Marchand wrote: > On Thu, Jul 2, 2020 at 12:05 AM Ilya Maximets <i.maximets@ovn.org> wrote: >> 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. > > In the documentation, example outputs could get outdated since we > directly pass dpdk output (/me still wants to shoot the dpdk global > log level that is just useless). > But I think it is still worth adding. > > I would see either in Documentation/howto/dpdk.rst or > Documentation/intro/install/dpdk.rst. > The latter seems the best fit: we have setup instructions, configuring > logs is close. > WDYT? install/dpdk.rst might be more appropriate. However, maybe it's enough to just create lib/dpdk-unixctl.man similar to lib/netdev-dpdk-unixctl.man ? We need it anyway to keep man pages updated. > > [snip] > >>> @@ -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. > > dpdk "dump" apis tend to have the same prototype, so yes it will save some code. > > [snip] > >>> + >>> + 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); > > No need for escaping? Yes. You're right. I'm not sure why we (me mostly) doing that sometimes in code... Some weird habits from shell scripting? I don't know. :) > > > Thanks for the review. >
On Thu, Jul 2, 2020 at 12:04 PM Ilya Maximets <i.maximets@ovn.org> wrote: > > On 7/2/20 10:25 AM, David Marchand wrote: > > On Thu, Jul 2, 2020 at 12:05 AM Ilya Maximets <i.maximets@ovn.org> wrote: > >> 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. > > > > In the documentation, example outputs could get outdated since we > > directly pass dpdk output (/me still wants to shoot the dpdk global > > log level that is just useless). > > But I think it is still worth adding. > > > > I would see either in Documentation/howto/dpdk.rst or > > Documentation/intro/install/dpdk.rst. > > The latter seems the best fit: we have setup instructions, configuring > > logs is close. > > WDYT? > > install/dpdk.rst might be more appropriate. > However, maybe it's enough to just create lib/dpdk-unixctl.man similar > to lib/netdev-dpdk-unixctl.man ? We need it anyway to keep man pages > updated. Indeed, I had missed this. Thanks, will do.
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); + 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". */ + 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"); + + 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; + } + 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); + 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;
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. This does not help when tracking issues in dpdk init itself: dump log levels right after init. Signed-off-by: David Marchand <david.marchand@redhat.com> --- lib/dpdk.c | 113 +++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 113 insertions(+)