X-Git-Url: https://git.whamcloud.com/?p=fs%2Flustre-release.git;a=blobdiff_plain;f=libcfs%2Flibcfs%2Ftracefile.c;h=2d0ec57c5d21d1a284174c1a64ce4fcd5ae0ca7b;hp=0c2e06a262bfdd804d2ce1bd580adc57b2ff031d;hb=068cf5c7cd29cc1c27effb71ff9b511d14207147;hpb=8a1d98bc86c87af064bbf87a2349cc314573dbc5 diff --git a/libcfs/libcfs/tracefile.c b/libcfs/libcfs/tracefile.c index 0c2e06a..2d0ec57 100644 --- a/libcfs/libcfs/tracefile.c +++ b/libcfs/libcfs/tracefile.c @@ -15,11 +15,7 @@ * * You should have received a copy of the GNU General Public License * version 2 along with this program; If not, see - * http://www.sun.com/software/products/lustre/docs/GPLv2.pdf - * - * Please contact Sun Microsystems, Inc., 4150 Network Circle, Santa Clara, - * CA 95054 USA or visit www.sun.com if you need additional information or - * have any questions. + * http://www.gnu.org/licenses/gpl-2.0.html * * GPL HEADER END */ @@ -27,7 +23,7 @@ * Copyright (c) 2008, 2010, Oracle and/or its affiliates. All rights reserved. * Use is subject to license terms. * - * Copyright (c) 2012, 2013, Intel Corporation. + * Copyright (c) 2012, 2017, Intel Corporation. */ /* * This file is part of Lustre, http://www.lustre.org/ @@ -44,22 +40,106 @@ #define LUSTRE_TRACEFILE_PRIVATE #include "tracefile.h" +#include +#include +#include +#include +#include +#include +#include +#include #include -/* XXX move things up to the top, comment */ +#define TCD_MAX_TYPES 8 + union cfs_trace_data_union (*cfs_trace_data[TCD_MAX_TYPES])[NR_CPUS] __cacheline_aligned; +char *cfs_trace_console_buffers[NR_CPUS][CFS_TCD_TYPE_MAX]; char cfs_tracefile[TRACEFILE_NAME_SIZE]; long long cfs_tracefile_size = CFS_TRACEFILE_SIZE; static struct tracefiled_ctl trace_tctl; -struct mutex cfs_trace_thread_mutex; +static DEFINE_MUTEX(cfs_trace_thread_mutex); static int thread_running = 0; -atomic_t cfs_tage_allocated = ATOMIC_INIT(0); +static atomic_t cfs_tage_allocated = ATOMIC_INIT(0); +static DECLARE_RWSEM(cfs_tracefile_sem); static void put_pages_on_tcd_daemon_list(struct page_collection *pc, struct cfs_trace_cpu_data *tcd); +/* trace file lock routines */ +/* The walking argument indicates the locking comes from all tcd types + * iterator and we must lock it and dissable local irqs to avoid deadlocks + * with other interrupt locks that might be happening. See LU-1311 + * for details. + */ +int cfs_trace_lock_tcd(struct cfs_trace_cpu_data *tcd, int walking) + __acquires(&tcd->tcd_lock) +{ + __LASSERT(tcd->tcd_type < CFS_TCD_TYPE_MAX); + if (tcd->tcd_type == CFS_TCD_TYPE_IRQ) + spin_lock_irqsave(&tcd->tcd_lock, tcd->tcd_lock_flags); + else if (tcd->tcd_type == CFS_TCD_TYPE_SOFTIRQ) + spin_lock_bh(&tcd->tcd_lock); + else if (unlikely(walking)) + spin_lock_irq(&tcd->tcd_lock); + else + spin_lock(&tcd->tcd_lock); + return 1; +} + +void cfs_trace_unlock_tcd(struct cfs_trace_cpu_data *tcd, int walking) + __releases(&tcd->tcd_lock) +{ + __LASSERT(tcd->tcd_type < CFS_TCD_TYPE_MAX); + if (tcd->tcd_type == CFS_TCD_TYPE_IRQ) + spin_unlock_irqrestore(&tcd->tcd_lock, tcd->tcd_lock_flags); + else if (tcd->tcd_type == CFS_TCD_TYPE_SOFTIRQ) + spin_unlock_bh(&tcd->tcd_lock); + else if (unlikely(walking)) + spin_unlock_irq(&tcd->tcd_lock); + else + spin_unlock(&tcd->tcd_lock); +} + +#define cfs_tcd_for_each(tcd, i, j) \ + for (i = 0; cfs_trace_data[i]; i++) \ + for (j = 0, ((tcd) = &(*cfs_trace_data[i])[j].tcd); \ + j < num_possible_cpus(); \ + j++, (tcd) = &(*cfs_trace_data[i])[j].tcd) + +#define cfs_tcd_for_each_type_lock(tcd, i, cpu) \ + for (i = 0; cfs_trace_data[i] && \ + (tcd = &(*cfs_trace_data[i])[cpu].tcd) && \ + cfs_trace_lock_tcd(tcd, 1); cfs_trace_unlock_tcd(tcd, 1), i++) + +enum cfs_trace_buf_type cfs_trace_buf_idx_get(void) +{ + if (in_irq()) + return CFS_TCD_TYPE_IRQ; + if (in_softirq()) + return CFS_TCD_TYPE_SOFTIRQ; + return CFS_TCD_TYPE_PROC; +} + +static inline struct cfs_trace_cpu_data * +cfs_trace_get_tcd(void) +{ + struct cfs_trace_cpu_data *tcd = + &(*cfs_trace_data[cfs_trace_buf_idx_get()])[get_cpu()].tcd; + + cfs_trace_lock_tcd(tcd, 0); + + return tcd; +} + +static inline void cfs_trace_put_tcd(struct cfs_trace_cpu_data *tcd) +{ + cfs_trace_unlock_tcd(tcd, 0); + + put_cpu(); +} + static inline struct cfs_trace_page * cfs_tage_from_list(struct list_head *list) { @@ -72,7 +152,7 @@ static struct cfs_trace_page *cfs_tage_alloc(gfp_t gfp) struct cfs_trace_page *tage; /* My caller is trying to free memory */ - if (!in_interrupt() && memory_pressure_get()) + if (!in_interrupt() && (current->flags & PF_MEMALLOC)) return NULL; /* @@ -114,27 +194,6 @@ static void cfs_tage_to_tail(struct cfs_trace_page *tage, list_move_tail(&tage->linkage, queue); } -int cfs_trace_refill_stock(struct cfs_trace_cpu_data *tcd, gfp_t gfp, - struct list_head *stock) -{ - int i; - - /* - * XXX nikita: do NOT call portals_debug_msg() (CDEBUG/ENTRY/EXIT) - * from here: this will lead to infinite recursion. - */ - - for (i = 0; i + tcd->tcd_cur_stock_pages < TCD_STOCK_PAGES ; ++ i) { - struct cfs_trace_page *tage; - - tage = cfs_tage_alloc(gfp); - if (tage == NULL) - break; - list_add_tail(&tage->linkage, stock); - } - return i; -} - /* return a page that has 'len' bytes left at the end */ static struct cfs_trace_page * cfs_trace_get_tage_try(struct cfs_trace_cpu_data *tcd, unsigned long len) @@ -144,7 +203,7 @@ cfs_trace_get_tage_try(struct cfs_trace_cpu_data *tcd, unsigned long len) if (tcd->tcd_cur_pages > 0) { __LASSERT(!list_empty(&tcd->tcd_pages)); tage = cfs_tage_from_list(tcd->tcd_pages.prev); - if (tage->used + len <= PAGE_CACHE_SIZE) + if (tage->used + len <= PAGE_SIZE) return tage; } @@ -156,11 +215,10 @@ cfs_trace_get_tage_try(struct cfs_trace_cpu_data *tcd, unsigned long len) } else { tage = cfs_tage_alloc(GFP_ATOMIC); if (unlikely(tage == NULL)) { - if ((!memory_pressure_get() || + if ((!(current->flags & PF_MEMALLOC) || in_interrupt()) && printk_ratelimit()) - printk(KERN_WARNING - "cannot allocate a tage (%ld)\n", - tcd->tcd_cur_pages); + pr_warn("Lustre: cannot allocate a tage (%ld)\n", + tcd->tcd_cur_pages); return NULL; } } @@ -196,8 +254,7 @@ static void cfs_tcd_shrink(struct cfs_trace_cpu_data *tcd) */ if (printk_ratelimit()) - printk(KERN_WARNING "debug daemon buffer overflowed; " - "discarding 10%% of pages (%d of %ld)\n", + pr_warn("Lustre: debug daemon buffer overflowed; discarding 10%% of pages (%d of %ld)\n", pgcount + 1, tcd->tcd_cur_pages); INIT_LIST_HEAD(&pc.pc_pages); @@ -223,9 +280,9 @@ static struct cfs_trace_page *cfs_trace_get_tage(struct cfs_trace_cpu_data *tcd, * from here: this will lead to infinite recursion. */ - if (len > PAGE_CACHE_SIZE) { - printk(KERN_ERR - "cowardly refusing to write %lu bytes in a page\n", len); + if (len > PAGE_SIZE) { + pr_err("LustreError: cowardly refusing to write %lu bytes in a page\n", + len); return NULL; } @@ -242,241 +299,303 @@ static struct cfs_trace_page *cfs_trace_get_tage(struct cfs_trace_cpu_data *tcd, return tage; } -int libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, - const char *format, ...) +static void cfs_set_ptldebug_header(struct ptldebug_header *header, + struct libcfs_debug_msg_data *msgdata, + unsigned long stack) { - va_list args; - int rc; + struct timespec64 ts; - va_start(args, format); - rc = libcfs_debug_vmsg2(msgdata, format, args, NULL); - va_end(args); + ktime_get_real_ts64(&ts); - return rc; + header->ph_subsys = msgdata->msg_subsys; + header->ph_mask = msgdata->msg_mask; + header->ph_cpu_id = smp_processor_id(); + header->ph_type = cfs_trace_buf_idx_get(); + /* y2038 safe since all user space treats this as unsigned, but + * will overflow in 2106 + */ + header->ph_sec = (u32)ts.tv_sec; + header->ph_usec = ts.tv_nsec / NSEC_PER_USEC; + header->ph_stack = stack; + header->ph_pid = current->pid; + header->ph_line_num = msgdata->msg_line; + header->ph_extern_pid = 0; } -EXPORT_SYMBOL(libcfs_debug_msg); -int libcfs_debug_vmsg2(struct libcfs_debug_msg_data *msgdata, - const char *format1, va_list args, - const char *format2, ...) +/** + * tty_write_msg - write a message to a certain tty, not just the console. + * @tty: the destination tty_struct + * @msg: the message to write + * + * tty_write_message is not exported, so write a same function for it + * + */ +static void tty_write_msg(struct tty_struct *tty, const char *msg) { - struct cfs_trace_cpu_data *tcd = NULL; - struct ptldebug_header header = {0}; - struct cfs_trace_page *tage; - /* string_buf is used only if tcd != NULL, and is always set then */ - char *string_buf = NULL; - char *debug_buf; - int known_size; - int needed = 85; /* average message length */ - int max_nob; - va_list ap; - int depth; - int i; - int remain; - int mask = msgdata->msg_mask; - char *file = (char *)msgdata->msg_file; - cfs_debug_limit_state_t *cdls = msgdata->msg_cdls; - - if (strchr(file, '/')) - file = strrchr(file, '/') + 1; - - tcd = cfs_trace_get_tcd(); - - /* cfs_trace_get_tcd() grabs a lock, which disables preemption and - * pins us to a particular CPU. This avoids an smp_processor_id() - * warning on Linux when debugging is enabled. */ - cfs_set_ptldebug_header(&header, msgdata, CDEBUG_STACK()); - - if (tcd == NULL) /* arch may not log in IRQ context */ - goto console; - - if (tcd->tcd_cur_pages == 0) - header.ph_flags |= PH_FLAG_FIRST_RECORD; - - if (tcd->tcd_shutting_down) { - cfs_trace_put_tcd(tcd); - tcd = NULL; - goto console; - } + mutex_lock(&tty->atomic_write_lock); + tty_lock(tty); + if (tty->ops->write && tty->count > 0) + tty->ops->write(tty, msg, strlen(msg)); + tty_unlock(tty); + mutex_unlock(&tty->atomic_write_lock); + wake_up_interruptible_poll(&tty->write_wait, POLLOUT); +} - depth = __current_nesting_level(); - known_size = strlen(file) + 1 + depth; - if (msgdata->msg_fn) - known_size += strlen(msgdata->msg_fn) + 1; +static void cfs_tty_write_message(const char *prefix, int mask, const char *msg) +{ + struct tty_struct *tty; + + tty = get_current_tty(); + if (!tty) + return; + + tty_write_msg(tty, prefix); + if ((mask & D_EMERG) || (mask & D_ERROR)) + tty_write_msg(tty, "Error"); + tty_write_msg(tty, ": "); + tty_write_msg(tty, msg); + tty_kref_put(tty); +} - if (libcfs_debug_binary) - known_size += sizeof(header); +static void cfs_print_to_console(struct ptldebug_header *hdr, int mask, + const char *buf, int len, const char *file, + const char *fn) +{ + char *prefix = "Lustre"; + + if (hdr->ph_subsys == S_LND || hdr->ph_subsys == S_LNET) + prefix = "LNet"; + + if (mask & D_CONSOLE) { + if (mask & D_EMERG) + pr_emerg("%sError: %.*s", prefix, len, buf); + else if (mask & D_ERROR) + pr_err("%sError: %.*s", prefix, len, buf); + else if (mask & D_WARNING) + pr_warn("%s: %.*s", prefix, len, buf); + else if (mask & libcfs_printk) + pr_info("%s: %.*s", prefix, len, buf); + } else { + if (mask & D_EMERG) + pr_emerg("%sError: %d:%d:(%s:%d:%s()) %.*s", prefix, + hdr->ph_pid, hdr->ph_extern_pid, file, + hdr->ph_line_num, fn, len, buf); + else if (mask & D_ERROR) + pr_err("%sError: %d:%d:(%s:%d:%s()) %.*s", prefix, + hdr->ph_pid, hdr->ph_extern_pid, file, + hdr->ph_line_num, fn, len, buf); + else if (mask & D_WARNING) + pr_warn("%s: %d:%d:(%s:%d:%s()) %.*s", prefix, + hdr->ph_pid, hdr->ph_extern_pid, file, + hdr->ph_line_num, fn, len, buf); + else if (mask & (D_CONSOLE | libcfs_printk)) + pr_info("%s: %.*s", prefix, len, buf); + } - /*/ - * '2' used because vsnprintf return real size required for output - * _without_ terminating NULL. - * if needed is to small for this format. - */ - for (i = 0; i < 2; i++) { - tage = cfs_trace_get_tage(tcd, needed + known_size + 1); - if (tage == NULL) { - if (needed + known_size > PAGE_CACHE_SIZE) - mask |= D_ERROR; - - cfs_trace_put_tcd(tcd); - tcd = NULL; - goto console; - } + if (mask & D_TTY) + cfs_tty_write_message(prefix, mask, buf); +} + +int libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, + const char *format, ...) +{ + struct cfs_trace_cpu_data *tcd = NULL; + struct ptldebug_header header = {0}; + struct cfs_trace_page *tage; + /* string_buf is used only if tcd != NULL, and is always set then */ + char *string_buf = NULL; + char *debug_buf; + int known_size; + int needed = 85; /* seeded with average message length */ + int max_nob; + va_list ap; + int retry; + int mask = msgdata->msg_mask; + char *file = (char *)msgdata->msg_file; + struct cfs_debug_limit_state *cdls = msgdata->msg_cdls; + + if (strchr(file, '/')) + file = strrchr(file, '/') + 1; + + tcd = cfs_trace_get_tcd(); + + /* cfs_trace_get_tcd() grabs a lock, which disables preemption and + * pins us to a particular CPU. This avoids an smp_processor_id() + * warning on Linux when debugging is enabled. + */ + cfs_set_ptldebug_header(&header, msgdata, CDEBUG_STACK()); + + if (!tcd) /* arch may not log in IRQ context */ + goto console; + + if (tcd->tcd_cur_pages == 0) + header.ph_flags |= PH_FLAG_FIRST_RECORD; + + if (tcd->tcd_shutting_down) { + cfs_trace_put_tcd(tcd); + tcd = NULL; + goto console; + } + + known_size = strlen(file) + 1; + if (msgdata->msg_fn) + known_size += strlen(msgdata->msg_fn) + 1; + + if (libcfs_debug_binary) + known_size += sizeof(header); + + /* + * May perform an additional pass to update 'needed' and increase + * tage buffer size to match vsnprintf reported size required + * On the second pass (retry=1) use vscnprintf [which returns + * number of bytes written not including the terminating nul] + * to clarify `needed` is used as number of bytes written + * for the remainder of this function + */ + for (retry = 0; retry < 2; retry++) { + tage = cfs_trace_get_tage(tcd, needed + known_size + 1); + if (!tage) { + if (needed + known_size > PAGE_SIZE) + mask |= D_ERROR; + + cfs_trace_put_tcd(tcd); + tcd = NULL; + goto console; + } string_buf = (char *)page_address(tage->page) + - tage->used + known_size; + tage->used + known_size; - max_nob = PAGE_CACHE_SIZE - tage->used - known_size; + max_nob = PAGE_SIZE - tage->used - known_size; if (max_nob <= 0) { - printk(KERN_EMERG "negative max_nob: %d\n", - max_nob); + pr_emerg("LustreError: negative max_nob: %d\n", + max_nob); mask |= D_ERROR; cfs_trace_put_tcd(tcd); tcd = NULL; goto console; } - needed = 0; - if (format1) { - va_copy(ap, args); - needed = vsnprintf(string_buf, max_nob, format1, ap); - va_end(ap); - } + va_start(ap, format); + if (retry) + needed = vscnprintf(string_buf, max_nob, format, ap); + else + needed = vsnprintf(string_buf, max_nob, format, ap); + va_end(ap); - if (format2) { - remain = max_nob - needed; - if (remain < 0) - remain = 0; - - va_start(ap, format2); - needed += vsnprintf(string_buf + needed, remain, - format2, ap); - va_end(ap); - } - - if (needed < max_nob) /* well. printing ok.. */ - break; - } + if (needed < max_nob) /* well. printing ok.. */ + break; + } - if (*(string_buf+needed-1) != '\n') - printk(KERN_INFO "format at %s:%d:%s doesn't end in " - "newline\n", file, msgdata->msg_line, msgdata->msg_fn); + /* `needed` is actual bytes written to string_buf */ + if (*(string_buf + needed - 1) != '\n') { + pr_info("Lustre: format at %s:%d:%s doesn't end in newline\n", + file, msgdata->msg_line, msgdata->msg_fn); + } else if (mask & D_TTY) { + /* TTY needs '\r\n' to move carriage to leftmost position */ + if (needed < 2 || *(string_buf + needed - 2) != '\r') + pr_info("Lustre: format at %s:%d:%s doesn't end in '\\r\\n'\n", + file, msgdata->msg_line, msgdata->msg_fn); + } - header.ph_len = known_size + needed; + header.ph_len = known_size + needed; debug_buf = (char *)page_address(tage->page) + tage->used; - if (libcfs_debug_binary) { - memcpy(debug_buf, &header, sizeof(header)); - tage->used += sizeof(header); - debug_buf += sizeof(header); - } - - /* indent message according to the nesting level */ - while (depth-- > 0) { - *(debug_buf++) = '.'; - ++ tage->used; - } + if (libcfs_debug_binary) { + memcpy(debug_buf, &header, sizeof(header)); + tage->used += sizeof(header); + debug_buf += sizeof(header); + } - strcpy(debug_buf, file); - tage->used += strlen(file) + 1; - debug_buf += strlen(file) + 1; + strlcpy(debug_buf, file, PAGE_SIZE - tage->used); + tage->used += strlen(file) + 1; + debug_buf += strlen(file) + 1; - if (msgdata->msg_fn) { - strcpy(debug_buf, msgdata->msg_fn); - tage->used += strlen(msgdata->msg_fn) + 1; - debug_buf += strlen(msgdata->msg_fn) + 1; - } + if (msgdata->msg_fn) { + strlcpy(debug_buf, msgdata->msg_fn, PAGE_SIZE - tage->used); + tage->used += strlen(msgdata->msg_fn) + 1; + debug_buf += strlen(msgdata->msg_fn) + 1; + } - __LASSERT(debug_buf == string_buf); + __LASSERT(debug_buf == string_buf); - tage->used += needed; - __LASSERT(tage->used <= PAGE_CACHE_SIZE); + tage->used += needed; + __LASSERT(tage->used <= PAGE_SIZE); console: - if ((mask & libcfs_printk) == 0) { - /* no console output requested */ - if (tcd != NULL) - cfs_trace_put_tcd(tcd); - return 1; - } + if ((mask & libcfs_printk) == 0) { + /* no console output requested */ + if (tcd != NULL) + cfs_trace_put_tcd(tcd); + return 1; + } - if (cdls != NULL) { - if (libcfs_console_ratelimit && - cdls->cdls_next != 0 && /* not first time ever */ - !cfs_time_after(cfs_time_current(), cdls->cdls_next)) { - /* skipping a console message */ - cdls->cdls_count++; - if (tcd != NULL) - cfs_trace_put_tcd(tcd); - return 1; - } + if (cdls != NULL) { + if (libcfs_console_ratelimit && + cdls->cdls_next != 0 && /* not first time ever */ + time_before(jiffies, cdls->cdls_next)) { + /* skipping a console message */ + cdls->cdls_count++; + if (tcd != NULL) + cfs_trace_put_tcd(tcd); + return 1; + } - if (cfs_time_after(cfs_time_current(), cdls->cdls_next + - libcfs_console_max_delay - + cfs_time_seconds(10))) { - /* last timeout was a long time ago */ - cdls->cdls_delay /= libcfs_console_backoff * 4; - } else { - cdls->cdls_delay *= libcfs_console_backoff; - } + if (time_after(jiffies, cdls->cdls_next + + libcfs_console_max_delay + + cfs_time_seconds(10))) { + /* last timeout was a long time ago */ + cdls->cdls_delay /= libcfs_console_backoff * 4; + } else { + cdls->cdls_delay *= libcfs_console_backoff; + } if (cdls->cdls_delay < libcfs_console_min_delay) cdls->cdls_delay = libcfs_console_min_delay; else if (cdls->cdls_delay > libcfs_console_max_delay) cdls->cdls_delay = libcfs_console_max_delay; - /* ensure cdls_next is never zero after it's been seen */ - cdls->cdls_next = (cfs_time_current() + cdls->cdls_delay) | 1; - } + /* ensure cdls_next is never zero after it's been seen */ + cdls->cdls_next = (jiffies + cdls->cdls_delay) | 1; + } - if (tcd != NULL) { - cfs_print_to_console(&header, mask, string_buf, needed, file, - msgdata->msg_fn); - cfs_trace_put_tcd(tcd); - } else { - string_buf = cfs_trace_get_console_buffer(); - - needed = 0; - if (format1 != NULL) { - va_copy(ap, args); - needed = vsnprintf(string_buf, - CFS_TRACE_CONSOLE_BUFFER_SIZE, - format1, ap); - va_end(ap); - } - if (format2 != NULL) { - remain = CFS_TRACE_CONSOLE_BUFFER_SIZE - needed; - if (remain > 0) { - va_start(ap, format2); - needed += vsnprintf(string_buf+needed, remain, - format2, ap); - va_end(ap); - } - } - cfs_print_to_console(&header, mask, - string_buf, needed, file, msgdata->msg_fn); + if (tcd) { + cfs_print_to_console(&header, mask, string_buf, needed, file, + msgdata->msg_fn); + cfs_trace_put_tcd(tcd); + } else { + string_buf = cfs_trace_get_console_buffer(); - cfs_trace_put_console_buffer(string_buf); - } + va_start(ap, format); + needed = vscnprintf(string_buf, CFS_TRACE_CONSOLE_BUFFER_SIZE, + format, ap); + va_end(ap); - if (cdls != NULL && cdls->cdls_count != 0) { - string_buf = cfs_trace_get_console_buffer(); + cfs_print_to_console(&header, mask, + string_buf, needed, file, msgdata->msg_fn); - needed = snprintf(string_buf, CFS_TRACE_CONSOLE_BUFFER_SIZE, - "Skipped %d previous similar message%s\n", - cdls->cdls_count, - (cdls->cdls_count > 1) ? "s" : ""); + put_cpu(); + } - cfs_print_to_console(&header, mask, - string_buf, needed, file, msgdata->msg_fn); + if (cdls != NULL && cdls->cdls_count != 0) { + string_buf = cfs_trace_get_console_buffer(); - cfs_trace_put_console_buffer(string_buf); - cdls->cdls_count = 0; - } + needed = scnprintf(string_buf, CFS_TRACE_CONSOLE_BUFFER_SIZE, + "Skipped %d previous similar message%s\n", + cdls->cdls_count, + (cdls->cdls_count > 1) ? "s" : ""); - return 0; + /* Do not allow print this to TTY */ + cfs_print_to_console(&header, mask & ~D_TTY, string_buf, + needed, file, msgdata->msg_fn); + + put_cpu(); + cdls->cdls_count = 0; + } + + return 0; } -EXPORT_SYMBOL(libcfs_debug_vmsg2); +EXPORT_SYMBOL(libcfs_debug_msg); void cfs_trace_assertion_failed(const char *str, @@ -671,17 +790,16 @@ int cfs_tracefile_dump_all_pages(char *filename) struct file *filp; struct cfs_trace_page *tage; struct cfs_trace_page *tmp; + char *buf; int rc; - DECL_MMSPACE; - - cfs_tracefile_write_lock(); + down_write(&cfs_tracefile_sem); filp = filp_open(filename, O_CREAT|O_EXCL|O_WRONLY|O_LARGEFILE, 0600); if (IS_ERR(filp)) { rc = PTR_ERR(filp); filp = NULL; - printk(KERN_ERR "LustreError: can't open %s for dump: rc %d\n", + pr_err("LustreError: can't open %s for dump: rc = %d\n", filename, rc); goto out; } @@ -693,18 +811,18 @@ int cfs_tracefile_dump_all_pages(char *filename) goto close; } - /* ok, for now, just write the pages. in the future we'll be building - * iobufs with the pages and calling generic_direct_IO */ - MMSPACE_OPEN; + /* ok, for now, just write the pages. in the future we'll be building + * iobufs with the pages and calling generic_direct_IO */ list_for_each_entry_safe(tage, tmp, &pc.pc_pages, linkage) { - __LASSERT_TAGE_INVARIANT(tage); + __LASSERT_TAGE_INVARIANT(tage); - rc = filp_write(filp, page_address(tage->page), - tage->used, filp_poff(filp)); + buf = kmap(tage->page); + rc = cfs_kernel_write(filp, buf, tage->used, &filp->f_pos); + kunmap(tage->page); if (rc != (int)tage->used) { - printk(KERN_WARNING "wanted to write %u but wrote " - "%d\n", tage->used, rc); + pr_warn("Lustre: wanted to write %u but wrote %d\n", + tage->used, rc); put_pages_back(&pc); __LASSERT(list_empty(&pc.pc_pages)); break; @@ -712,14 +830,14 @@ int cfs_tracefile_dump_all_pages(char *filename) list_del(&tage->linkage); cfs_tage_free(tage); } - MMSPACE_CLOSE; - rc = filp_fsync(filp, 0, LLONG_MAX); + + rc = vfs_fsync_range(filp, 0, LLONG_MAX, 1); if (rc) - printk(KERN_ERR "sync returns %d\n", rc); + pr_err("LustreError: sync returns: rc = %d\n", rc); close: filp_close(filp, NULL); out: - cfs_tracefile_write_unlock(); + up_write(&cfs_tracefile_sem); return rc; } @@ -741,19 +859,18 @@ void cfs_trace_flush_pages(void) } int cfs_trace_copyin_string(char *knl_buffer, int knl_buffer_nob, - const char *usr_buffer, int usr_buffer_nob) + const char __user *usr_buffer, int usr_buffer_nob) { int nob; if (usr_buffer_nob > knl_buffer_nob) return -EOVERFLOW; - if (copy_from_user((void *)knl_buffer, - (void *)usr_buffer, usr_buffer_nob)) + if (copy_from_user(knl_buffer, usr_buffer, usr_buffer_nob)) return -EFAULT; nob = strnlen(knl_buffer, usr_buffer_nob); - while (nob-- >= 0) /* strip trailing whitespace */ + while (--nob >= 0) /* strip trailing whitespace */ if (!isspace(knl_buffer[nob])) break; @@ -768,7 +885,7 @@ int cfs_trace_copyin_string(char *knl_buffer, int knl_buffer_nob, } EXPORT_SYMBOL(cfs_trace_copyin_string); -int cfs_trace_copyout_string(char *usr_buffer, int usr_buffer_nob, +int cfs_trace_copyout_string(char __user *usr_buffer, int usr_buffer_nob, const char *knl_buffer, char *append) { /* NB if 'append' != NULL, it's a single character to append to the @@ -795,22 +912,17 @@ EXPORT_SYMBOL(cfs_trace_copyout_string); int cfs_trace_allocate_string_buffer(char **str, int nob) { - if (nob > 2 * PAGE_CACHE_SIZE) /* string must be "sensible" */ + if (nob > 2 * PAGE_SIZE) /* string must be "sensible" */ return -EINVAL; - *str = kmalloc(nob, GFP_IOFS | __GFP_ZERO); + *str = kmalloc(nob, GFP_KERNEL | __GFP_ZERO); if (*str == NULL) return -ENOMEM; return 0; } -void cfs_trace_free_string_buffer(char *str, int nob) -{ - kfree(str); -} - -int cfs_trace_dump_debug_buffer_usrstr(void *usr_str, int usr_str_nob) +int cfs_trace_dump_debug_buffer_usrstr(void __user *usr_str, int usr_str_nob) { char *str; int rc; @@ -830,7 +942,7 @@ int cfs_trace_dump_debug_buffer_usrstr(void *usr_str, int usr_str_nob) } rc = cfs_tracefile_dump_all_pages(str); out: - cfs_trace_free_string_buffer(str, usr_str_nob + 1); + kfree(str); return rc; } @@ -838,21 +950,24 @@ int cfs_trace_daemon_command(char *str) { int rc = 0; - cfs_tracefile_write_lock(); + down_write(&cfs_tracefile_sem); if (strcmp(str, "stop") == 0) { - cfs_tracefile_write_unlock(); + up_write(&cfs_tracefile_sem); cfs_trace_stop_thread(); - cfs_tracefile_write_lock(); + down_write(&cfs_tracefile_sem); memset(cfs_tracefile, 0, sizeof(cfs_tracefile)); - } else if (strncmp(str, "size=", 5) == 0) { - cfs_tracefile_size = simple_strtoul(str + 5, NULL, 0); - if (cfs_tracefile_size < 10 || cfs_tracefile_size > 20480) - cfs_tracefile_size = CFS_TRACEFILE_SIZE; - else - cfs_tracefile_size <<= 20; + } else if (strncmp(str, "size=", 5) == 0) { + unsigned long tmp; + rc = kstrtoul(str + 5, 10, &tmp); + if (!rc) { + if (tmp < 10 || tmp > 20480) + cfs_tracefile_size = CFS_TRACEFILE_SIZE; + else + cfs_tracefile_size = tmp << 20; + } } else if (strlen(str) >= sizeof(cfs_tracefile)) { rc = -ENAMETOOLONG; } else if (str[0] != '/') { @@ -860,19 +975,17 @@ int cfs_trace_daemon_command(char *str) } else { strcpy(cfs_tracefile, str); - printk(KERN_INFO - "Lustre: debug daemon will attempt to start writing " - "to %s (%lukB max)\n", cfs_tracefile, - (long)(cfs_tracefile_size >> 10)); + pr_info("Lustre: debug daemon will attempt to start writing to %s (%lukB max)\n", + cfs_tracefile, (long)(cfs_tracefile_size >> 10)); cfs_trace_start_thread(); } - cfs_tracefile_write_unlock(); + up_write(&cfs_tracefile_sem); return rc; } -int cfs_trace_daemon_command_usrstr(void *usr_str, int usr_str_nob) +int cfs_trace_daemon_command_usrstr(void __user *usr_str, int usr_str_nob) { char *str; int rc; @@ -886,7 +999,7 @@ int cfs_trace_daemon_command_usrstr(void *usr_str, int usr_str_nob) if (rc == 0) rc = cfs_trace_daemon_command(str); - cfs_trace_free_string_buffer(str, usr_str_nob + 1); + kfree(str); return rc; } @@ -894,47 +1007,34 @@ int cfs_trace_set_debug_mb(int mb) { int i; int j; - int pages; - int limit = cfs_trace_max_debug_mb(); + unsigned long pages; + unsigned long total_mb = (cfs_totalram_pages() >> (20 - PAGE_SHIFT)); + unsigned long limit = max_t(unsigned long, 512, (total_mb * 4) / 5); struct cfs_trace_cpu_data *tcd; if (mb < num_possible_cpus()) { - printk(KERN_WARNING - "Lustre: %d MB is too small for debug buffer size, " - "setting it to %d MB.\n", mb, num_possible_cpus()); + pr_warn("Lustre: %d MB is too small for debug buffer size, setting it to %d MB.\n", + mb, num_possible_cpus()); mb = num_possible_cpus(); } if (mb > limit) { - printk(KERN_WARNING - "Lustre: %d MB is too large for debug buffer size, " - "setting it to %d MB.\n", mb, limit); + pr_warn("Lustre: %d MB is too large for debug buffer size, setting it to %lu MB.\n", + mb, limit); mb = limit; } mb /= num_possible_cpus(); - pages = mb << (20 - PAGE_CACHE_SHIFT); + pages = mb << (20 - PAGE_SHIFT); - cfs_tracefile_write_lock(); + down_write(&cfs_tracefile_sem); cfs_tcd_for_each(tcd, i, j) tcd->tcd_max_pages = (pages * tcd->tcd_pages_factor) / 100; - cfs_tracefile_write_unlock(); + up_write(&cfs_tracefile_sem); - return 0; -} - -int cfs_trace_set_debug_mb_usrstr(void *usr_str, int usr_str_nob) -{ - char str[32]; - int rc; - - rc = cfs_trace_copyin_string(str, sizeof(str), usr_str, usr_str_nob); - if (rc < 0) - return rc; - - return cfs_trace_set_debug_mb(simple_strtoul(str, NULL, 0)); + return mb; } int cfs_trace_get_debug_mb(void) @@ -944,14 +1044,14 @@ int cfs_trace_get_debug_mb(void) struct cfs_trace_cpu_data *tcd; int total_pages = 0; - cfs_tracefile_read_lock(); + down_read(&cfs_tracefile_sem); cfs_tcd_for_each(tcd, i, j) total_pages += tcd->tcd_max_pages; - cfs_tracefile_read_unlock(); + up_read(&cfs_tracefile_sem); - return (total_pages >> (20 - PAGE_CACHE_SHIFT)) + 1; + return (total_pages >> (20 - PAGE_SHIFT)) + 1; } static int tracefiled(void *arg) @@ -961,18 +1061,17 @@ static int tracefiled(void *arg) struct cfs_trace_page *tage; struct cfs_trace_page *tmp; struct file *filp; + char *buf; int last_loop = 0; int rc; - DECL_MMSPACE; - /* we're started late enough that we pick up init's fs context */ /* this is so broken in uml? what on earth is going on? */ complete(&tctl->tctl_start); while (1) { - wait_queue_t __wait; + wait_queue_entry_t __wait; pc.pc_want_daemon_pages = 0; collect_pages(&pc); @@ -980,7 +1079,7 @@ static int tracefiled(void *arg) goto end_loop; filp = NULL; - cfs_tracefile_read_lock(); + down_read(&cfs_tracefile_sem); if (cfs_tracefile[0] != 0) { filp = filp_open(cfs_tracefile, O_CREAT | O_RDWR | O_LARGEFILE, @@ -988,64 +1087,60 @@ static int tracefiled(void *arg) if (IS_ERR(filp)) { rc = PTR_ERR(filp); filp = NULL; - printk(KERN_WARNING "couldn't open %s: " - "%d\n", cfs_tracefile, rc); + pr_warn("Lustre: couldn't open %s: rc = %d\n", + cfs_tracefile, rc); } } - cfs_tracefile_read_unlock(); + up_read(&cfs_tracefile_sem); if (filp == NULL) { put_pages_on_daemon_list(&pc); __LASSERT(list_empty(&pc.pc_pages)); goto end_loop; } - MMSPACE_OPEN; - list_for_each_entry_safe(tage, tmp, &pc.pc_pages, linkage) { - static loff_t f_pos; + struct dentry *de = file_dentry(filp); + static loff_t f_pos; - __LASSERT_TAGE_INVARIANT(tage); + __LASSERT_TAGE_INVARIANT(tage); - if (f_pos >= (off_t)cfs_tracefile_size) - f_pos = 0; - else if (f_pos > (off_t)filp_size(filp)) - f_pos = filp_size(filp); + if (f_pos >= (off_t)cfs_tracefile_size) + f_pos = 0; + else if (f_pos > i_size_read(de->d_inode)) + f_pos = i_size_read(de->d_inode); - rc = filp_write(filp, page_address(tage->page), - tage->used, &f_pos); + buf = kmap(tage->page); + rc = cfs_kernel_write(filp, buf, tage->used, &f_pos); + kunmap(tage->page); if (rc != (int)tage->used) { - printk(KERN_WARNING "wanted to write %u " - "but wrote %d\n", tage->used, rc); + pr_warn("Lustre: wanted to write %u but wrote %d\n", + tage->used, rc); put_pages_back(&pc); __LASSERT(list_empty(&pc.pc_pages)); break; } } - MMSPACE_CLOSE; filp_close(filp, NULL); put_pages_on_daemon_list(&pc); if (!list_empty(&pc.pc_pages)) { int i; - printk(KERN_ALERT "Lustre: trace pages aren't " - " empty\n"); - printk(KERN_ERR "total cpus(%d): ", - num_possible_cpus()); + pr_alert("Lustre: trace pages aren't empty\n"); + pr_err("Lustre: total cpus(%d): ", num_possible_cpus()); for (i = 0; i < num_possible_cpus(); i++) if (cpu_online(i)) - printk(KERN_ERR "%d(on) ", i); + pr_cont("%d(on) ", i); else - printk(KERN_ERR "%d(off) ", i); - printk(KERN_ERR "\n"); + pr_cont("%d(off) ", i); + pr_cont("\n"); i = 0; list_for_each_entry_safe(tage, tmp, &pc.pc_pages, - linkage) - printk(KERN_ERR "page %d belongs to cpu " - "%d\n", ++i, tage->cpu); - printk(KERN_ERR "There are %d pages unwritten\n", - i); + linkage) + pr_err("Lustre: page %d belongs to cpu %d\n", + ++i, tage->cpu); + pr_err("Lustre: There are %d pages unwritten\n", i); } __LASSERT(list_empty(&pc.pc_pages)); end_loop: @@ -1057,11 +1152,9 @@ end_loop: break; } } - init_waitqueue_entry_current(&__wait); + init_waitqueue_entry(&__wait, current); add_wait_queue(&tctl->tctl_waitq, &__wait); - set_current_state(TASK_INTERRUPTIBLE); - waitq_timedwait(&__wait, TASK_INTERRUPTIBLE, - cfs_time_seconds(1)); + schedule_timeout_interruptible(cfs_time_seconds(1)); remove_wait_queue(&tctl->tctl_waitq, &__wait); } complete(&tctl->tctl_stop); @@ -1100,8 +1193,7 @@ void cfs_trace_stop_thread(void) mutex_lock(&cfs_trace_thread_mutex); if (thread_running) { - printk(KERN_INFO - "Lustre: shutting down debug daemon thread...\n"); + pr_info("Lustre: shutting down debug daemon thread...\n"); atomic_set(&tctl->tctl_shutdown, 1); wait_for_completion(&tctl->tctl_stop); thread_running = 0; @@ -1109,21 +1201,39 @@ void cfs_trace_stop_thread(void) mutex_unlock(&cfs_trace_thread_mutex); } +/* percents to share the total debug memory for each type */ +static unsigned int pages_factor[CFS_TCD_TYPE_MAX] = { + 80, /* 80% pages for CFS_TCD_TYPE_PROC */ + 10, /* 10% pages for CFS_TCD_TYPE_SOFTIRQ */ + 10 /* 10% pages for CFS_TCD_TYPE_IRQ */ +}; + int cfs_tracefile_init(int max_pages) { struct cfs_trace_cpu_data *tcd; - int i; - int j; - int rc; - int factor; + int i; + int j; - rc = cfs_tracefile_init_arch(); - if (rc != 0) - return rc; + /* initialize trace_data */ + memset(cfs_trace_data, 0, sizeof(cfs_trace_data)); + for (i = 0; i < CFS_TCD_TYPE_MAX; i++) { + cfs_trace_data[i] = + kmalloc_array(num_possible_cpus(), + sizeof(union cfs_trace_data_union), + GFP_KERNEL); + if (!cfs_trace_data[i]) + goto out_trace_data; + } + /* arch related info initialized */ cfs_tcd_for_each(tcd, i, j) { - /* tcd_pages_factor is initialized int tracefile_init_arch. */ - factor = tcd->tcd_pages_factor; + int factor = pages_factor[i]; + + spin_lock_init(&tcd->tcd_lock); + tcd->tcd_pages_factor = factor; + tcd->tcd_type = i; + tcd->tcd_cpu = j; + INIT_LIST_HEAD(&tcd->tcd_pages); INIT_LIST_HEAD(&tcd->tcd_stock_pages); INIT_LIST_HEAD(&tcd->tcd_daemon_pages); @@ -1134,7 +1244,31 @@ int cfs_tracefile_init(int max_pages) LASSERT(tcd->tcd_max_pages > 0); tcd->tcd_shutting_down = 0; } + + for (i = 0; i < num_possible_cpus(); i++) + for (j = 0; j < 3; j++) { + cfs_trace_console_buffers[i][j] = + kmalloc(CFS_TRACE_CONSOLE_BUFFER_SIZE, + GFP_KERNEL); + if (!cfs_trace_console_buffers[i][j]) + goto out_buffers; + } + return 0; + +out_buffers: + for (i = 0; i < num_possible_cpus(); i++) + for (j = 0; j < 3; j++) { + kfree(cfs_trace_console_buffers[i][j]); + cfs_trace_console_buffers[i][j] = NULL; + } +out_trace_data: + for (i = 0; cfs_trace_data[i]; i++) { + kfree(cfs_trace_data[i]); + cfs_trace_data[i] = NULL; + } + pr_err("lnet: Not enough memory\n"); + return -ENOMEM; } static void trace_cleanup_on_all_cpus(void) @@ -1146,6 +1280,9 @@ static void trace_cleanup_on_all_cpus(void) for_each_possible_cpu(cpu) { cfs_tcd_for_each_type_lock(tcd, i, cpu) { + if (!tcd->tcd_pages_factor) + /* Not initialised */ + continue; tcd->tcd_shutting_down = 1; list_for_each_entry_safe(tage, tmp, &tcd->tcd_pages, linkage) { @@ -1162,12 +1299,23 @@ static void trace_cleanup_on_all_cpus(void) static void cfs_trace_cleanup(void) { struct page_collection pc; + int i; + int j; INIT_LIST_HEAD(&pc.pc_pages); trace_cleanup_on_all_cpus(); - cfs_tracefile_fini_arch(); + for (i = 0; i < num_possible_cpus(); i++) + for (j = 0; j < 3; j++) { + kfree(cfs_trace_console_buffers[i][j]); + cfs_trace_console_buffers[i][j] = NULL; + } + + for (i = 0; cfs_trace_data[i]; i++) { + kfree(cfs_trace_data[i]); + cfs_trace_data[i] = NULL; + } } void cfs_tracefile_exit(void)