From 8597aa5a7b322f6134988b37cb32195d7bf14010 Mon Sep 17 00:00:00 2001 From: Curt Bruns Date: Thu, 2 Jun 2022 10:58:14 -0700 Subject: [PATCH] test: optimize the print statements in aer test The aer test print statements were overly complicated for multi process mode, so a macro was created to simplify them. The macro will prepend "[Child]" to the child process print statements to make it easier to see which process is doing the printouts. Signed-off-by: Curt Bruns Change-Id: I0ecc5e2526b156fa7f98d44c745408ba922ebeff Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/12881 Community-CI: Broadcom CI Tested-by: SPDK CI Jenkins Reviewed-by: Paul Luse Reviewed-by: Jim Harris Reviewed-by: Shuhei Matsumoto --- test/nvme/aer/aer.c | 156 ++++++++++++++++++++++---------------------- 1 file changed, 79 insertions(+), 77 deletions(-) diff --git a/test/nvme/aer/aer.c b/test/nvme/aer/aer.c index d5f6d576e..a988bf848 100644 --- a/test/nvme/aer/aer.c +++ b/test/nvme/aer/aer.c @@ -28,6 +28,10 @@ static int g_num_devs = 0; #define foreach_dev(iter) \ for (iter = g_devs; iter - g_devs < g_num_devs; iter++) +#define AER_PRINTF(format, ...) printf("%s" format, g_parent_process ? "" : "[Child] ", \ + ##__VA_ARGS__) +#define AER_FPRINTF(f, format, ...) fprintf(f, "%s" format, g_parent_process ? \ + "" : "[Child] ", ##__VA_ARGS__) static int g_outstanding_commands = 0; static int g_aer_done = 0; @@ -42,7 +46,7 @@ static int g_enable_temp_test = 0; static uint32_t g_expected_ns_test = 0; /* For multi-process test */ static int g_multi_process_test = 0; -static bool g_parent_process; +static bool g_parent_process = true; static const char *g_sem_init_name = "/init"; static const char *g_sem_child_name = "/child"; static sem_t *g_sem_init_id; @@ -56,7 +60,7 @@ set_temp_completion(void *cb_arg, const struct spdk_nvme_cpl *cpl) g_outstanding_commands--; if (spdk_nvme_cpl_is_error(cpl)) { - printf("%s: set feature (temp threshold) failed\n", dev->name); + AER_PRINTF("%s: set feature (temp threshold) failed\n", dev->name); g_failed = 1; return; } @@ -80,8 +84,7 @@ set_temp_threshold(struct dev *dev, uint32_t temp) if (rc == 0) { g_outstanding_commands++; } else { - fprintf(stderr, "Submitting Admin cmd failed with rc: %d (%s)\n", \ - rc, (g_parent_process ? "Parent" : "Child")); + AER_FPRINTF(stderr, "Submitting Admin cmd failed with rc: %d\n", rc); } return rc; @@ -95,14 +98,14 @@ get_temp_completion(void *cb_arg, const struct spdk_nvme_cpl *cpl) g_outstanding_commands--; if (spdk_nvme_cpl_is_error(cpl)) { - printf("%s: get feature (temp threshold) failed\n", dev->name); + AER_PRINTF("%s: get feature (temp threshold) failed\n", dev->name); g_failed = 1; return; } dev->orig_temp_threshold = cpl->cdw0; - printf("%s: original temperature threshold: %u Kelvin (%d Celsius)\n", - dev->name, dev->orig_temp_threshold, dev->orig_temp_threshold - 273); + AER_PRINTF("%s: original temperature threshold: %u Kelvin (%d Celsius)\n", + dev->name, dev->orig_temp_threshold, dev->orig_temp_threshold - 273); g_temperature_done++; } @@ -127,8 +130,8 @@ get_temp_threshold(struct dev *dev) static void print_health_page(struct dev *dev, struct spdk_nvme_health_information_page *hip) { - printf("%s: Current Temperature: %u Kelvin (%d Celsius)\n", - dev->name, hip->temperature, hip->temperature - 273); + AER_PRINTF("%s: Current Temperature: %u Kelvin (%d Celsius)\n", + dev->name, hip->temperature, hip->temperature - 273); } static void @@ -139,7 +142,7 @@ get_health_log_page_completion(void *cb_arg, const struct spdk_nvme_cpl *cpl) g_outstanding_commands--; if (spdk_nvme_cpl_is_error(cpl)) { - printf("%s: get log page failed\n", dev->name); + AER_PRINTF("%s: get log page failed\n", dev->name); g_failed = 1; return; } @@ -154,7 +157,8 @@ get_health_log_page(struct dev *dev) int rc; rc = spdk_nvme_ctrlr_cmd_get_log_page(dev->ctrlr, SPDK_NVME_LOG_HEALTH_INFORMATION, - SPDK_NVME_GLOBAL_NS_TAG, dev->health_page, sizeof(*dev->health_page), 0, + SPDK_NVME_GLOBAL_NS_TAG, dev->health_page, + sizeof(*dev->health_page), 0, get_health_log_page_completion, dev); if (rc == 0) { @@ -202,14 +206,13 @@ aer_cb(void *arg, const struct spdk_nvme_cpl *cpl) log_page_id = aen_cpl.bits.log_page_identifier; if (spdk_nvme_cpl_is_error(cpl)) { - fprintf(stderr, "%s: AER failed\n", dev->name); + AER_FPRINTF(stderr, "%s: AER failed\n", dev->name); g_failed = 1; return; } - printf("%s: aer_cb for log page %d, aen_event_type: 0x%02x, aen_event_info: 0x%02x (%s)\n", \ - dev->name, log_page_id, aen_event_type, aen_event_info, \ - (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("%s: aer_cb for log page %d, aen_event_type: 0x%02x, aen_event_info: 0x%02x\n", + dev->name, log_page_id, aen_event_type, aen_event_info); /* Temp Test: Verify proper EventType, Event Info and Log Page. * NOTE: QEMU NVMe controllers return Spare Below Threshold Status event info * instead of Temperate Threshold even info which is why it's used in the check @@ -220,46 +223,43 @@ aer_cb(void *arg, const struct spdk_nvme_cpl *cpl) ((aen_event_info == SPDK_NVME_ASYNC_EVENT_TEMPERATURE_THRESHOLD) || \ (aen_event_info == SPDK_NVME_ASYNC_EVENT_SPARE_BELOW_THRESHOLD))) { /* Set the temperature threshold back to the original value to stop triggering */ - printf("aer_cb - Resetting Temp Threshold for device: %s (%s)\n", \ - dev->name, (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("aer_cb - Resetting Temp Threshold for device: %s\n", dev->name); set_temp_threshold(dev, dev->orig_temp_threshold); get_health_log_page(dev); } else if (log_page_id == SPDK_NVME_LOG_CHANGED_NS_LIST) { - printf("aer_cb - Changed Namespace (%s)\n", \ - (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("aer_cb - Changed Namespace\n"); get_ns_state_test(dev, g_expected_ns_test); g_aer_done++; } else { - printf("aer_cb - Unknown Log Page (%s)\n", \ - (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("aer_cb - Unknown Log Page\n"); } } static void usage(const char *program_name) { - printf("%s [options]", program_name); - printf("\n"); - printf("options:\n"); - printf(" -g use single file descriptor for DPDK memory segments]\n"); - printf(" -T enable temperature tests\n"); - printf(" -n expected Namespace attribute notice ID\n"); - printf(" -t touch specified file when ready to receive AER\n"); - printf(" -r trid remote NVMe over Fabrics target address\n"); - printf(" Format: 'key:value [key:value] ...'\n"); - printf(" Keys:\n"); - printf(" trtype Transport type (e.g. RDMA)\n"); - printf(" adrfam Address family (e.g. IPv4, IPv6)\n"); - printf(" traddr Transport address (e.g. 192.168.100.8)\n"); - printf(" trsvcid Transport service identifier (e.g. 4420)\n"); - printf(" subnqn Subsystem NQN (default: %s)\n", SPDK_NVMF_DISCOVERY_NQN); - printf(" Example: -r 'trtype:RDMA adrfam:IPv4 traddr:192.168.100.8 trsvcid:4420'\n"); + AER_PRINTF("%s [options]", program_name); + AER_PRINTF("\n"); + AER_PRINTF("options:\n"); + AER_PRINTF(" -g use single file descriptor for DPDK memory segments]\n"); + AER_PRINTF(" -T enable temperature tests\n"); + AER_PRINTF(" -n expected Namespace attribute notice ID\n"); + AER_PRINTF(" -t touch specified file when ready to receive AER\n"); + AER_PRINTF(" -r trid remote NVMe over Fabrics target address\n"); + AER_PRINTF(" Format: 'key:value [key:value] ...'\n"); + AER_PRINTF(" Keys:\n"); + AER_PRINTF(" trtype Transport type (e.g. RDMA)\n"); + AER_PRINTF(" adrfam Address family (e.g. IPv4, IPv6)\n"); + AER_PRINTF(" traddr Transport address (e.g. 192.168.100.8)\n"); + AER_PRINTF(" trsvcid Transport service identifier (e.g. 4420)\n"); + AER_PRINTF(" subnqn Subsystem NQN (default: %s)\n", SPDK_NVMF_DISCOVERY_NQN); + AER_PRINTF(" Example: -r 'trtype:RDMA adrfam:IPv4 traddr:192.168.100.8 trsvcid:4420'\n"); spdk_log_usage(stdout, "-L"); - printf(" -i shared memory group ID\n"); - printf(" -m Multi-Process AER Test (only with Temp Test)\n"); - printf(" -H show this usage\n"); + AER_PRINTF(" -i shared memory group ID\n"); + AER_PRINTF(" -m Multi-Process AER Test (only with Temp Test)\n"); + AER_PRINTF(" -H show this usage\n"); } static int @@ -276,7 +276,7 @@ parse_args(int argc, char **argv, struct spdk_env_opts *env_opts) case 'n': val = spdk_strtol(optarg, 10); if (val < 0) { - fprintf(stderr, "Invalid NS attribute notice ID\n"); + AER_FPRINTF(stderr, "Invalid NS attribute notice ID\n"); return val; } g_expected_ns_test = (uint32_t)val; @@ -286,7 +286,7 @@ parse_args(int argc, char **argv, struct spdk_env_opts *env_opts) break; case 'r': if (spdk_nvme_transport_id_parse(&g_trid, optarg) != 0) { - fprintf(stderr, "Error parsing transport address\n"); + AER_FPRINTF(stderr, "Error parsing transport address\n"); return 1; } break; @@ -296,7 +296,7 @@ parse_args(int argc, char **argv, struct spdk_env_opts *env_opts) case 'L': rc = spdk_log_set_flag(optarg); if (rc < 0) { - fprintf(stderr, "unknown flag\n"); + AER_FPRINTF(stderr, "unknown flag\n"); usage(argv[0]); exit(EXIT_FAILURE); } @@ -313,7 +313,7 @@ parse_args(int argc, char **argv, struct spdk_env_opts *env_opts) case 'i': env_opts->shm_id = spdk_strtol(optarg, 10); if (env_opts->shm_id < 0) { - fprintf(stderr, "Invalid shared memory ID\n"); + AER_FPRINTF(stderr, "Invalid shared memory ID\n"); return env_opts->shm_id; } break; @@ -333,7 +333,7 @@ static bool probe_cb(void *cb_ctx, const struct spdk_nvme_transport_id *trid, struct spdk_nvme_ctrlr_opts *opts) { - printf("Attaching to %s\n", trid->traddr); + AER_PRINTF("Attaching to %s\n", trid->traddr); return true; } @@ -352,12 +352,12 @@ attach_cb(void *cb_ctx, const struct spdk_nvme_transport_id *trid, snprintf(dev->name, sizeof(dev->name), "%s", trid->traddr); - printf("Attached to %s\n", dev->name); + AER_PRINTF("Attached to %s\n", dev->name); dev->health_page = spdk_zmalloc(sizeof(*dev->health_page), 4096, NULL, SPDK_ENV_LCORE_ID_ANY, SPDK_MALLOC_DMA); if (dev->health_page == NULL) { - printf("Allocation error (health page)\n"); + AER_PRINTF("Allocation error (health page)\n"); g_failed = 1; } } @@ -370,7 +370,7 @@ get_feature_test_cb(void *cb_arg, const struct spdk_nvme_cpl *cpl) g_outstanding_commands--; if (spdk_nvme_cpl_is_error(cpl)) { - printf("%s: get number of queues failed\n", dev->name); + AER_PRINTF("%s: get number of queues failed\n", dev->name); g_failed = 1; return; } @@ -394,7 +394,7 @@ get_feature_test(struct dev *dev) cmd.cdw10_bits.get_features.fid = SPDK_NVME_FEAT_NUMBER_OF_QUEUES; if (spdk_nvme_ctrlr_cmd_admin_raw(dev->ctrlr, &cmd, NULL, 0, get_feature_test_cb, dev) != 0) { - printf("Failed to send Get Features command for dev=%p\n", dev); + AER_PRINTF("Failed to send Get Features command for dev=%p\n", dev); g_failed = 1; return; } @@ -407,8 +407,7 @@ spdk_aer_temperature_test(void) { struct dev *dev; - printf("Getting orig temperature thresholds of all controllers (%s)\n", - (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("Getting orig temperature thresholds of all controllers\n"); foreach_dev(dev) { /* Get the original temperature threshold */ get_temp_threshold(dev); @@ -441,13 +440,13 @@ spdk_aer_temperature_test(void) if (g_multi_process_test) { sem_wait(g_sem_child_id); } - printf("Setting all controllers temperature threshold low to trigger AER\n"); + AER_PRINTF("Setting all controllers temperature threshold low to trigger AER\n"); foreach_dev(dev) { /* Set the temperature threshold to a low value */ set_temp_threshold(dev, 200); } - printf("Waiting for all controllers temperature threshold to be set lower\n"); + AER_PRINTF("Waiting for all controllers temperature threshold to be set lower\n"); while (!g_failed && (g_temperature_done < g_num_devs)) { foreach_dev(dev) { spdk_nvme_ctrlr_process_admin_completions(dev->ctrlr); @@ -460,8 +459,7 @@ spdk_aer_temperature_test(void) } } - printf("Waiting for all controllers to trigger AER and reset threshold (%s)\n", - (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("Waiting for all controllers to trigger AER and reset threshold\n"); /* Let parent know init is done and it's okay to continue */ if (!g_parent_process) { sem_post(g_sem_child_id); @@ -487,7 +485,7 @@ spdk_aer_changed_ns_test(void) g_aer_done = 0; - printf("Starting namespace attribute notice tests for all controllers...\n"); + AER_PRINTF("Starting namespace attribute notice tests for all controllers...\n"); foreach_dev(dev) { get_feature_test(dev); @@ -520,12 +518,12 @@ setup_multi_process(void) /* If AEN test was killed, remove named semaphore to start again */ rc = sem_unlink(g_sem_init_name); if (rc < 0 && errno != ENOENT) { - fprintf(stderr, "Init semaphore removal failure: %s", spdk_strerror(errno)); + AER_FPRINTF(stderr, "Init semaphore removal failure: %s", spdk_strerror(errno)); return rc; } rc = sem_unlink(g_sem_child_name); if (rc < 0 && errno != ENOENT) { - fprintf(stderr, "Child semaphore removal failure: %s", spdk_strerror(errno)); + AER_FPRINTF(stderr, "Child semaphore removal failure: %s", spdk_strerror(errno)); return rc; } pid = fork(); @@ -533,12 +531,13 @@ setup_multi_process(void) perror("Failed to fork\n"); return -1; } else if (pid == 0) { - printf("Child process pid: %d\n", getpid()); + AER_PRINTF("Child process pid: %d\n", getpid()); g_parent_process = false; g_sem_init_id = sem_open(g_sem_init_name, O_CREAT, 0600, 0); g_sem_child_id = sem_open(g_sem_child_name, O_CREAT, 0600, 0); if ((g_sem_init_id == SEM_FAILED) || (g_sem_child_id == SEM_FAILED)) { - fprintf(stderr, "Sem Open failed for child: %s\n", spdk_strerror(errno)); + AER_FPRINTF(stderr, "Sem Open failed for child: %s\n", + spdk_strerror(errno)); return -1; } } @@ -548,7 +547,8 @@ setup_multi_process(void) g_sem_init_id = sem_open(g_sem_init_name, O_CREAT, 0600, 0); g_sem_child_id = sem_open(g_sem_child_name, O_CREAT, 0600, 0); if ((g_sem_init_id == SEM_FAILED) || (g_sem_child_id == SEM_FAILED)) { - fprintf(stderr, "Sem Open failed for parent: %s\n", spdk_strerror(errno)); + AER_FPRINTF(stderr, "Sem Open failed for parent: %s\n", + spdk_strerror(errno)); return -1; } } @@ -571,16 +571,16 @@ int main(int argc, char **argv) if (g_multi_process_test) { /* Multi-Process test only available with Temp Test */ if (!g_enable_temp_test) { - fprintf(stderr, "Multi Process test only available with Temp Test (-T)\n"); + AER_FPRINTF(stderr, "Multi Process only available with Temp Test (-T)\n"); return 1; } if (opts.shm_id < 0) { - fprintf(stderr, "Multi Process requires shared memory id (-i )\n"); + AER_FPRINTF(stderr, "Multi Process requires shared memory id (-i )\n"); return 1; } rc = setup_multi_process(); if (rc != 0) { - fprintf(stderr, "Multi Process test failed to setup\n"); + AER_FPRINTF(stderr, "Multi Process test failed to setup\n"); return rc; } } else { @@ -600,25 +600,24 @@ int main(int argc, char **argv) */ if (!g_parent_process) { if (sem_wait(g_sem_init_id) < 0) { - fprintf(stderr, "sem_wait failed for child process\n"); + AER_FPRINTF(stderr, "sem_wait failed for child process\n"); return (-1); } } if (spdk_env_init(&opts) < 0) { - fprintf(stderr, "Unable to initialize SPDK env\n"); + AER_FPRINTF(stderr, "Unable to initialize SPDK env\n"); return 1; } - printf("Asynchronous Event Request test (%s)\n", - (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("Asynchronous Event Request test\n"); if (spdk_nvme_probe(&g_trid, NULL, probe_cb, attach_cb, NULL) != 0) { - fprintf(stderr, "spdk_nvme_probe() failed\n"); + AER_FPRINTF(stderr, "spdk_nvme_probe() failed\n"); return 1; } if (g_num_devs == 0) { - fprintf(stderr, "No controllers found - exiting\n"); + AER_FPRINTF(stderr, "No controllers found - exiting\n"); g_failed = 1; } if (g_failed) { @@ -626,10 +625,10 @@ int main(int argc, char **argv) } if (g_parent_process && g_enable_temp_test) { - printf("Reset controller to setup AER completions for this process\n"); + AER_PRINTF("Reset controller to setup AER completions for this process\n"); foreach_dev(dev) { if (spdk_nvme_ctrlr_reset(dev->ctrlr) < 0) { - fprintf(stderr, "nvme reset failed.\n"); + AER_FPRINTF(stderr, "nvme reset failed.\n"); return -1; } } @@ -639,7 +638,7 @@ int main(int argc, char **argv) sem_post(g_sem_init_id); } - printf("Registering asynchronous event callbacks...\n"); + AER_PRINTF("Registering asynchronous event callbacks...\n"); foreach_dev(dev) { spdk_nvme_ctrlr_register_aer_callback(dev->ctrlr, aer_cb, dev); } @@ -649,7 +648,8 @@ int main(int argc, char **argv) fd = open(g_touch_file, O_CREAT | O_EXCL | O_RDWR, S_IFREG); if (fd == -1) { - fprintf(stderr, "Could not touch %s (%s).\n", g_touch_file, strerror(errno)); + AER_FPRINTF(stderr, "Could not touch %s (%s).\n", g_touch_file, + strerror(errno)); g_failed = true; goto done; } @@ -670,7 +670,7 @@ int main(int argc, char **argv) } } - printf("Cleaning up...(%s)\n", (g_parent_process ? "Parent" : "Child")); + AER_PRINTF("Cleaning up...\n"); while (g_outstanding_commands) { foreach_dev(dev) { @@ -704,7 +704,8 @@ int main(int argc, char **argv) done: cleanup(); - /* Wait for child process to finish and verify it finished correctly before detaching resources */ + /* Wait for child process to finish and verify it finished correctly before detaching + * resources */ if (g_multi_process_test && g_parent_process) { int status; sem_post(g_sem_init_id); @@ -712,7 +713,8 @@ done: if (WIFEXITED(status)) { /* Child ended normally */ if (WEXITSTATUS(status) != 0) { - fprintf(stderr, "Child Failed with status: %d.\n", (int8_t)(WEXITSTATUS(status))); + AER_FPRINTF(stderr, "Child Failed with status: %d.\n", + (int8_t)(WEXITSTATUS(status))); g_failed = true; } }