/*************************************************************************** * * Copyright (C) 2001 International Business Machines * All rights reserved. * * This file is part of the GPFS mmfslinux kernel module. * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions * are met: * * 1. Redistributions of source code must retain the above copyright notice, * this list of conditions and the following disclaimer. * 2. Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in the * documentation and/or other materials provided with the distribution. * 3. The name of the author may not be used to endorse or promote products * derived from this software without specific prior written * permission. * * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. * IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, * PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; * OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, * WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR * OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF * ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. * *************************************************************************** */ static char sccsid[] = "@(#)37 1.36 src/avs/fs/mmfs/ts/kernext/gpl-linux/lxtrace.c, mmfs, avs_rgpfs24, rgpfs240610b 10/31/05 10:36:03"; /************************************************************************** * * lxtrace : the command. Turns tracing on/off and formats trace files. * * "lxtrace {on hw[,hw[,hw...]] [trcFile [filesize [bufsize]]]" } * {off } * {format [-T] [-v] [-t formatFile] [-o outFile] [trcFile] } * * on - begins tracing * off - stops tracing * hw - hookword (identifies traces to be captured) * This is a comma-separated list (up to LXTRACE_MAX_HW) * trcFile - path to the file where output is written * filesize - maximum size (bytes) of the wrap-around file * A filesize of 0 will cause the file NOT to wrap * bufsize - the size of buffer to used by the device * to record trace records * * For debug/testing purposes, the following additional options * are defined: * "lxtrace dump // returns state information in a buffer * fsync // flush buffered records to the read buffer * **************************************************************************/ #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include /* Convenience macros for printing error and debug messages */ #define DP(fmt,args...) fprintf(stderr, fmt, ## args) #ifdef LXTRACE_DEBUG #define DFP(fmt,args...) fprintf(stderr, fmt, ## args) #else #define DFP(fmt,args...) ((void)0) #endif #define ROUNDUP(_addr, _align) \ (((long)_addr + (long)_align - 1L) & ~((long)_align - 1L)) /* Examples of formatted trace output: Default options: Timestamp Pid COMPONENT_TAG: application trace record ----------- ----- --------------------------------------- 0.000000 21499 TRACE_VNODE: gpfs_i_revalidate enter: -v option: Timestamp Pid P Hookword COMPONENT_TAG: application trace record ----------- ----- - -------- --------------------------------------- 0.000000 21499 1 307004B3 TRACE_VNODE: gpfs_i_revalidate enter: -T option: Timestamp Pid COMPONENT_TAG: application trace record ---------------- ----- --------------------------------------- 970706704.711164 21499 TRACE_VNODE: gpfs_i_revalidate enter: -T and -v options: Timestamp Pid P Hookword COMPONENT_TAG: application trace record ---------------- ----- - -------- --------------------------------------- 970706704.711164 21499 1 307004B3 TRACE_VNODE: gpfs_i_revalidate enter: */ /* Define fragments of header lines and the corresponding trace printf format strings for each field on a trace output line */ #define H1_TS " Timestamp " #define H2_TS "----------- " #define FMT_TS "%4d.%06d " #define H1_TS_T " Timestamp " #define H2_TS_T "----------------- " #define FMT_TS_T "%10d.%06d " #define H1_PID " Pid " #define H2_PID "------ " #define FMT_PID "%6d " #define H1_P_HW "" #define H2_P_HW "" #define FMT_P_HW "" #define H1_P_HW_V "P B Hookword " #define H2_P_HW_V "- - -------- " #define FMT_P_HW_V "%1d %1d %08X " #define H1_TAG "COMPONENT_TAG: application trace record\n" #define H2_TAG "---------------------------------------\n" #define FMT_TAG "%s: " /* Bytes in an "_id2name" formatting substitution */ #define TRC_MAX_ID2NAME 128 #ifndef O_DIRECT #ifdef GPFS_ARCH_PPC64 #define O_DIRECT 0400000 #else #define O_DIRECT 040000 #endif #endif #ifdef __64BIT__ typedef long long argType; #define ARGLEN sizeof(long long) #define TRC_ARG(N) (((long long *)&application_data)[N]) #else typedef int argType; #define ARGLEN sizeof(int) #define TRC_ARG(N) (((int *)&application_data)[N]) #endif // __64BIT__ #define TRC_ARGLIST argP[0] , argP[1] , argP[2] , argP[3] , argP[4] , argP[5], \ argP[6] , argP[7] , argP[8] , argP[9] , argP[10], argP[11],\ argP[12], argP[13], argP[14], argP[15], argP[16], argP[17],\ argP[18], argP[19] /* Offsets of the various fields in the formatting file */ #define GFR_TRCID 0 #define GFR_HOOKID 15 #define GFR_COMPID 20 #define GFR_FORMAT 40 /* Max length of COMPID in the formatting file */ # define MAX_COMPID_LEN (GFR_FORMAT - GFR_COMPID - 1) /* Thread IDs greater than this are really message handlers. FirstMsgHandlerThread is also defined in ThreadNames.h. */ #define FirstMsgHandlerThread 0x120 /* Size of the hash tables for in-memory format file and its hash functions. HOOK_HASH is for looking up format strings by hook id. I2N_HASH is for looking up id2name conversions by conversion name and id value; the I2NHASH hash function uses the first 4 chars of the conversion name, relying on the fact that these names are at least 4 chars long, because they all end in "_id2name". */ #define HOOK_HASH_TABLE_SIZE 0x10000 #define HOOKHASH(H) ((H) & 0xFFFF) #define I2N_HASH_TABLE_SIZE 0x4000 #ifndef ALIGNED_DATA_ACCESS #define I2NHASH(F,I) ((*(int*)(F) + (I)) & 0x3FFF) #else static inline int I2NHASH(char *F, int I) { int tmp; memcpy(&tmp, F, sizeof(int)); return (tmp + I) & 0x3FFF; } #endif /* combined device and application trace data headers */ typedef struct trc_hdrs_t { trc_header_t hdr; /* device header */ trc_datahdr_t rec; /* application header */ } trc_hdrs_t; /* id2name conversion specifier. */ typedef struct i2nSpec_t { int argNum; // number of the argument to be converted char *i2nNameP; // conversion function name } i2nSpec_t; /* Each format record has one of these headers describing it. */ typedef struct fmtDesc_t { int hookid; // hookid or id2name value char *cidP; // component identifier or id2name tag char *fmtP; // format string or id2name string unsigned int llmask; // bitvector indicating %ll arguments i2nSpec_t *i2nSpecP; // array of id2name conversion specifiers struct fmtDesc_t *fmtNextP; // next in the hash chain } fmtDesc_t; /* Hash tables for finding format records. */ fmtDesc_t * hookHashP[HOOK_HASH_TABLE_SIZE]; fmtDesc_t * i2nHashP[I2N_HASH_TABLE_SIZE]; /* Hash lookup statistics */ static int nHookLookup = 0; static int nHookCheck = 0; static int nI2NLookup = 0; static int nI2NCheck = 0; static int nI2NFail = 0; /* static state information */ static int TraceHandle = -1;// file descriptor for the trace device static int out_fd; // file descriptor for the (raw trace) output file static int outSize; // out_fd filesize static int bufSize; // size of the trace buffers (device and daemon) static char *bufP; // the daemon trace read buffer #if LINUX_KERNEL_VERSION >= 2060000 #define LXTRACE_USE_DIO #endif #ifdef LXTRACE_USE_DIO #define MAXAIOBUFS 10 static char *aiobufP[MAXAIOBUFS]; // the daemon 4k aligned trace write buffer static char *wbufP[MAXAIOBUFS]; // the daemon orginal trace write buffer static int wrapBytes=0; // bytes leftover after last DIO write #endif static int nWraps; // number of times the output file has wrapped static off_t currentPos; // position of next write to output file static off_t fileEnd=0; // position of next write to output file /* The previous time is used to validate a wrap point when we think we've encountered one. */ static struct timeval prevTime; /* Keep track of start/end times in the trace file */ static time_t startTime, stopTime; static char *formatFileP; // malloc'ed buffer holding formatting data static char *fmtDescSpaceP; // fmtData_t space for each format record static int allowed_usec_wobble = 2; // allowed timestamp wobble before declaring a wrap. /* Convert ascii representation of a hexadecimal to int */ int axtoi(char s[]) { int i, n; n = 0; for (i = 0; s[i] != '\0'; i++) { if (s[i] >= '0' && s[i] <= '9') n = 16 * n + (s[i] - '0'); else if (s[i] >= 'A' && s[i] <= 'F') n = 16 * n + (s[i] - 'A' + 10); else if (s[i] >= 'a' && s[i] <= 'f') n = 16 * n + (s[i] - 'a' + 10); else break; } return n; } /* Convert timestamp to string format. */ extern char *ctime_r(const time_t *, char *); char *fmtTime(time_t time, char *timeStr) { /* ctime_r returns a null-terminated, readable string that includes * a newline char which we remove. When ctime_r cannot convert the * supplied timestamp, it returns NULL. */ if (!ctime_r(&time, timeStr)) return "unknown"; timeStr[strlen(timeStr) - 1] = '\0'; return timeStr; } #define TIMEVAL_ZERO ((struct timeval){0,0}) static struct timeval wrap_prev = TIMEVAL_ZERO; static struct timeval wrap_next = TIMEVAL_ZERO; /* isWrapPoint: * See if consecutive timestamps are backwards (indicates a wrap-point). */ int isWrapPoint(struct timeval prev, struct timeval next) { /* Detect timestamps going backwards. This could be the wrap-point * or just wobble. */ if ((prev.tv_sec > next.tv_sec) || ((prev.tv_sec == next.tv_sec) && (prev.tv_usec - next.tv_usec > allowed_usec_wobble))) { /* Prepare for simple subtraction (do any necessary borrowing) */ if (prev.tv_usec < next.tv_usec) { prev.tv_usec += 1000000; prev.tv_sec -= 1; } DFP("isWrapPoint: wrap delta %d.%06d (prev %d.06d, next %d.06d)\n", (prev.tv_sec - next.tv_sec), (prev.tv_usec - next.tv_usec), prev.tv_sec, prev.tv_usec, next.tv_sec, next.tv_usec); /* Detect and warn if multiple wrap points are detected. */ if (((wrap_prev.tv_sec != 0) && ((wrap_prev.tv_sec != prev.tv_sec) || (wrap_prev.tv_usec != prev.tv_usec))) || ((wrap_next.tv_sec != 0) && ((wrap_next.tv_sec != next.tv_sec) || (wrap_next.tv_usec != next.tv_usec)))) { DP("Multiple wrap-points found:\n"); DP("\t%d.%06d-%d.%06d (delta %d.%06d)\n", wrap_prev.tv_sec, wrap_prev.tv_usec, wrap_next.tv_sec, wrap_next.tv_usec, (wrap_prev.tv_sec - wrap_next.tv_sec), (wrap_prev.tv_usec - wrap_next.tv_usec)); DP("\t%d.%06d-%d.%06d (delta %d.%06d)\n", prev.tv_sec, prev.tv_usec, next.tv_sec, next.tv_usec, (prev.tv_sec - next.tv_sec), (prev.tv_usec - next.tv_usec)); } /* Keep track of what we have now declared to be a wrap point */ wrap_prev = prev; wrap_next = next; return true; } return false; } /* Parse a quoted format string: removes enclosing quotes, removes trailing white-space, and converts escape sequences \n, \r, \t, \", etc. Also examines '%' format arguments and computes a bitvector that indicates which of the arguments are long longs (%ll..). The converted string is placed in outP; the i'th bit in *llmaskP is set if the i'th argument is a long long. It's ok to call this function to convert a string in-place (outP == inP), since the conversion only makes the string shorter (removes surrounding quotes and reduces escape sequences to a single char). Returns a pointer to the next character in inP following the ending quotes, or NULL if there are no more characters following the quoted string. */ char *ParseFormatString(char *inP, char *outP, unsigned int *llmaskP) { char *initialOutP = outP; int b = 1; /* skip initial quote */ if (*inP == '"') inP++; /* copy string until ending quote */ *llmaskP = 0; while (*inP && *inP != '"') { if (*inP == '\\' && *(inP + 1)) { inP++; switch(*inP) { case 'n': *outP++ = '\n'; inP++; break; case 'r': *outP++ = '\r'; inP++; break; case 't': *outP++ = '\t'; inP++; break; default: *outP++ = *inP++; } } else if (*inP == '%') { *outP++ = *inP++; if (*inP == '%') *outP++ = *inP++; else { if (*inP == '+' | *inP == '-') *outP++ = *inP++; while (isdigit(*inP)) *outP++ = *inP++; if (*inP == 'l' && *(inP+1) == 'l') *llmaskP |= b; b <<= 1; } } else *outP++ = *inP++; } /* remove trailing white space from the string */ while (outP > initialOutP && isspace(outP[-1])) outP--; *outP = '\0'; /* Return pointer to next character after the string or NULL if no ending quote was found */ return *inP? inP + 1: NULL; } /* Parse a string containing a list of id2name conversion specifiers of the form "$n=xxx_id2name $m=yyy_id2name ...". Returns a "null-terminted" array of i2nSpec_t structures, i.e., the array contains one more entry than the number of conversion specifiers found, and argNum/i2nNameP in the last array entry are set to 0/NULL. */ i2nSpec_t *ParseI2N(char *i2nP, unsigned int llmask) { i2nSpec_t i2n[LXTRACE_MAX_FORMAT_SUBS]; i2nSpec_t *i2nSpecP; char *p; int n, argNum, a, nll; unsigned int m; for (n = 0, p = strtok(i2nP, " \t\n"); p && n < LXTRACE_MAX_FORMAT_SUBS; n++, p = strtok(NULL, " \t\n")) { if (*p != '$') break; p++; argNum = atoi(p); p = strchr(p, '='); if (argNum <= 0 || p == NULL) break; #ifndef __64BIT__ /* The "n" in "$n=" signifies that the "n"th parameter needs substitution. However, we need to account for any double-word ("%ll") values (will be taking two positions) in the arglist and adjust accordingly. The llmask parameter indicates which arguments are of the %ll form. Count the bits in llmask before the point of the substitution and add the count to the argNum value. */ if (llmask) { nll = 0; for (a = 1, m = llmask; a < argNum && m; a++, m >>= 1) { if (m & 1) nll++; } argNum += nll; } #endif // __64BIT__ i2n[n].argNum = argNum; i2n[n].i2nNameP = p + 1; } if (n == 0) return NULL; // ?? print msg about bad id2name specifiers i2nSpecP = (i2nSpec_t *)malloc((n + 1)*sizeof(i2nSpec_t)); if (i2nSpecP != NULL) { memcpy(i2nSpecP, i2n, n*sizeof(i2nSpec_t)); i2nSpecP[n].argNum = 0; i2nSpecP[n].i2nNameP = NULL; } return i2nSpecP; } /* The formatting records are read into memory and parsed. A fmtDesc_t header is constructed for each and is then inserted into a hash table. */ int BuildFormatTable(FILE *fP) { char buf[2048]; long fileSize; /* size (bytes) of the formatting file */ int nRecords; /* Number of records in the formatting file */ int hookid; /* hookid of current record */ int hashVal; /* hash value */ struct fmtDesc_t *nextDescP; char *curFmtRecordP, *nextFmtRecordP; char *trcidP; char *hookP; char *cidP; char *fmtP; int i; #ifdef DBGASSERTS char *formatFileEndP; char *fmtDescSpaceEndP; #endif // DBGASSERTS /* Clear all entries in the hash table */ memset(hookHashP, 0, sizeof(hookHashP)); memset(i2nHashP, 0, sizeof(i2nHashP)); rewind(fP); /* Count the number of formatting records */ nRecords = 0; while (fgets(buf, sizeof(buf), fP) != NULL) nRecords += 1; /* Now that we are at the end of the file, see how big it is */ fileSize = ftell(fP); if (fileSize < 0) return errno; /* Allocate the buffer for the file contents. Add 1 for possible trailing zero. */ if (NULL == (formatFileP = (char *)malloc(fileSize+1))) return ENOMEM; /* Allocate space for the fmtData_t for all of the records. */ if (NULL == (fmtDescSpaceP = (char *)malloc(nRecords * sizeof(fmtDesc_t)))) return ENOMEM; nextDescP = (fmtDesc_t *)fmtDescSpaceP; #ifdef DBGASSERTS formatFileEndP = formatFileP + fileSize; fmtDescSpaceEndP = fmtDescSpaceP + (nRecords * sizeof(fmtDesc_t)); #endif // DBGASSERTS rewind(fP); /* back to the beginning of the file */ /* Read each record in one-at-a-time, parse the record, and insert it into the right hash table. */ curFmtRecordP = formatFileP; while (fgets(curFmtRecordP, sizeof(buf), fP) != NULL) { nextFmtRecordP = curFmtRecordP + strlen(curFmtRecordP); /* The TRCID identifier, hookid, component id, and format string are at fixed offsets */ trcidP = curFmtRecordP + GFR_TRCID; hookP = curFmtRecordP + GFR_HOOKID; cidP = curFmtRecordP + GFR_COMPID; fmtP = curFmtRecordP + GFR_FORMAT; /* parse the format record. */ hookid = axtoi(hookP) & 0x0000FFFF; nextDescP->hookid = hookid; nextDescP->cidP = strtok(cidP, " "); nextDescP->fmtP = fmtP; /* find the end of the format string */ fmtP = ParseFormatString(fmtP, fmtP, &nextDescP->llmask); /* check for id2name conversion specifiers following the format string */ nextDescP->i2nSpecP = NULL; if (fmtP) { while (isspace(*fmtP)) fmtP++; if (*fmtP) nextDescP->i2nSpecP = ParseI2N(fmtP, nextDescP->llmask); } /* Place the format record descriptor into the right hash table. */ if (strncmp(trcidP, "TRCID_", 6) == 0) { /* this record contains a format string */ strcat(nextDescP->fmtP, "\n"); hashVal = HOOKHASH(hookid); nextDescP->fmtNextP = hookHashP[hashVal]; hookHashP[hashVal] = nextDescP; } else { /* this record contains an id2name conversion value */ hashVal = I2NHASH(nextDescP->cidP, hookid); nextDescP->fmtNextP = i2nHashP[hashVal]; i2nHashP[hashVal] = nextDescP; } /* Advance to the next fmtDesc and format record */ nextDescP++; curFmtRecordP = nextFmtRecordP; } #ifdef DBGASSERTS /* verify that we didn't overrun our buffers */ if ((char *)nextDescP > fmtDescSpaceEndP) { DP("lxtrace format: overwrote format descriptor memory!\n"); return -1; } if (nextFmtRecordP > formatFileEndP) { DP("lxtrace format: overwrote format file memory!\n"); return -1; } #endif // DBGASSERTS return 0; } /* Find a format record by hookid. */ int GetFormatRecord(FILE *fP, int hookid, char **cidPP, char **fmtPP, unsigned int *llmaskP, i2nSpec_t **i2nPP) { fmtDesc_t *nextP; DFP("GetFormatRecord(0x%X, 0x%X, 0x%X, 0x%X, 0x%X)\n", fP, hookid, bufSize, bufP, cidPP); nHookLookup++; /* search hash chain for the specified hookid */ for (nextP = hookHashP[HOOKHASH(hookid)]; nextP != NULL; nextP = nextP->fmtNextP) { nHookCheck++; /* Check whether hookid matches. */ if (nextP->hookid == hookid) { /* Hookid and the record type match. Copy to work area. */ *cidPP = nextP->cidP; *fmtPP = nextP->fmtP; *llmaskP = nextP->llmask; *i2nPP = nextP->i2nSpecP; DFP("GetFormatRecord for id %X is: %s\n", hookid, *fmtPP); return 0; } } /* not found */ return -1; } /* Find an id2name string by conversion name ("tag") and id value */ int GetID2NameRecord(FILE *fP, char *tagP, int id, int bufSize, char *bufP) { fmtDesc_t *nextP; DFP("GetID2NameRecord(0x%X, 0x%X, 0x%X, 0x%X, 0x%X)\n", fP, tagP, id, bufSize, bufP); nI2NLookup++; /* search hash chain for the specified hookid and tag */ for (nextP = i2nHashP[I2NHASH(tagP, id)]; nextP != NULL; nextP = nextP->fmtNextP) { nI2NCheck++; /* Check whether hookid and tag match. */ if (nextP->hookid == id && strncmp(nextP->cidP, tagP, MAX_COMPID_LEN) == 0) { DFP("GetID2NameRecord for id %X is: %s\n", id, nextP->fmtP); strncpy(bufP, nextP->fmtP, bufSize); return 0; } } /* not found */ nI2NFail++; return -1; } /* Read the next trace header from the raw trace file. Normally, this just involves the read() for the specified file. However, it also needs to check for wrapping of the file and make the necessary adjustments when we reach the wrap point. */ int ReadNextTrcHeader(FILE *raw_fp, trc_hdrs_t *hdrP) { int nRead; off_t off1, off2; if (0 < (nRead = fread(hdrP, 1, sizeof(trc_hdrs_t), raw_fp))) { /* Successful read. Validate the header. */ if (hdrP->hdr.trMagic != LXTRACE_MAGIC) { /* Maybe we've reached the wrap point. See if we can get oriented. Backup and try 1 byte further until we find a valid header. This should be the wrap point. If we can verify this, return the header. */ fseek(raw_fp, 1-nRead, SEEK_CUR); off1 = ftell(raw_fp) - 1; while (0 < (nRead = fread(hdrP, 1, sizeof(trc_hdrs_t), raw_fp))) { /* Keep inching forward looking for a valid device header that * includes timestamps that also indicate a wrap ocurred. */ if ((hdrP->hdr.trMagic == LXTRACE_MAGIC) && isWrapPoint(prevTime, hdrP->hdr.trTime)) { DFP("ReadNextTrcHeader: wrap point between %d.%d and %d.%d\n", hdrP->hdr.trTime.tv_sec, hdrP->hdr.trTime.tv_usec, prevTime.tv_sec, prevTime.tv_usec); /* We've found what appears to be a valid header. */ prevTime = hdrP->hdr.trTime; /* timestamp of the last valid record */ nWraps += 1; DFP("ReadNextTrcHeader: wrap point at %d gap %d\n", off1, off2-off1); /* Save the oldest timestamp that we've found */ if (hdrP->hdr.trTime.tv_sec < startTime) startTime = hdrP->hdr.trTime.tv_sec; return nRead; } else if (hdrP->hdr.trMagic == LXTRACE_MAGIC) { /* We've found a valid header some ways from the beginning of the file, but it's not a wrap point. This could be due to some garbage in the file. Try to skip garbage data. */ /* timestamp of the last valid record */ prevTime = hdrP->hdr.trTime; /* Save the latest timestamp we've found */ stopTime = hdrP->hdr.trTime.tv_sec; /* Save the oldest timestamp that we've found */ if (hdrP->hdr.trTime.tv_sec < startTime) startTime = hdrP->hdr.trTime.tv_sec; return nRead; } fseek(raw_fp, 1-nRead, SEEK_CUR); off2 = ftell(raw_fp); } DP("lxtrace format: ReadNextTrcHeader failed to find a valid record!\n"); } else { /* Valid header found, but this could still be a wrap-point if the * alignment worked out exactly. */ if (isWrapPoint(prevTime, hdrP->hdr.trTime)) { DFP("ReadNextTrcHeader: wrap point between %d.%d and %d.%d\n", hdrP->hdr.trTime.tv_sec, hdrP->hdr.trTime.tv_usec, prevTime.tv_sec, prevTime.tv_usec); nWraps += 1; DFP("ReadNextTrcHeader: wrap point at %d gap %d\n", off1, off2-off1); /* timestamp of the last valid record */ prevTime = hdrP->hdr.trTime; /* Save the oldest timestamp that we've found */ if (hdrP->hdr.trTime.tv_sec < startTime) startTime = hdrP->hdr.trTime.tv_sec; } else { /* timestamp of the last valid record */ prevTime = hdrP->hdr.trTime; /* Save the latest timestamp we've found */ stopTime = hdrP->hdr.trTime.tv_sec; /* Save the oldest timestamp that we've found */ if (hdrP->hdr.trTime.tv_sec < startTime) startTime = hdrP->hdr.trTime.tv_sec; } } } return nRead; } #ifdef LXTRACE_USE_DIO #include static struct aiocb aiocb[MAXAIOBUFS] = {0}; static int aioStarted[MAXAIOBUFS] = {0}; static int numBuf = 0; static char wrapBuf[4096]; // bytes that didn't make the last dio write. inline void aioWait(int numBuf) { int i,rc; const struct aiocb *aioP[]={&aiocb[numBuf]}; if(aioStarted[numBuf]) { rc=aio_suspend(aioP, 1, NULL); if(rc==0) { size_t lrc = aio_return(&aiocb[numBuf]); aioStarted[numBuf]=0; DFP("aioWait aio_return[%d] %d\n", numBuf, rc); } } } inline void aioWrite(char* bufP, int wBytes) { int rc; bzero(&aiocb[numBuf], sizeof(struct aiocb)); aiocb[numBuf].aio_buf=bufP; aiocb[numBuf].aio_nbytes=wBytes; aiocb[numBuf].aio_offset=currentPos; aiocb[numBuf].aio_fildes=out_fd; aiocb[numBuf].aio_sigevent.sigev_notify=SIGEV_NONE; rc=aio_write(&aiocb[numBuf]); DFP("aioWrite %d bytes at offset %d numBuf %d \n", wBytes, currentPos, numBuf); aioStarted[numBuf]=1; numBuf = (numBuf + 1) % MAXAIOBUFS; } #endif /* ProcessBuffer reads from the trace device and writes to the output file. This is a function used by the trace daemon when handling SIGIO from the device or after fsync() as the device is being closed. */ void ProcessBuffer() { int rc, nBytes; retry: #ifdef LXTRACE_USE_DIO aioWait(numBuf); #endif /* Issue a read for one buffer to the trace device */ DFP("trace daemon about to read %d bytes\n", bufSize); nBytes = read(TraceHandle, bufP, bufSize); DFP("trace daemon read %d bytes\n", nBytes); if (nBytes == -1) { DP("trace daemon read error %d\n", errno); close(TraceHandle); close(out_fd); _exit(1); } if (nBytes > 0) { /* Check the output file wrap-size and handle if it has been reached. */ if ((out_fd > 2) && (outSize > 0) && ((currentPos + nBytes) > outSize)) { #ifdef LXTRACE_USE_DIO /* Write any leftover bytes as a full block and setup to truncate on exit any data that may have extended past this point from the last time we wrapped. */ memset(aiobufP[numBuf], 0, 4096); memcpy(aiobufP[numBuf], wrapBuf, wrapBytes); fileEnd=currentPos + wrapBytes; wrapBytes = 0; aioWrite(aiobufP[numBuf], 4096); aioWait(numBuf); #else /* Truncate any data that may have extended past this point from the last time we wrapped. Seek back to the top of the file and continue. */ DFP("trace daemon wrapping file at length %d\n", currentPos); lseek(out_fd, 0, SEEK_SET); ftruncate(out_fd, currentPos); #endif currentPos = 0; } /* Every trace record starts with a header (trc_hdrs_t) that includes * a magic number. If we ever get a buffer that doesn't start * properly, write some debug information and refuse to write it * to the trace file. */ if (((trc_hdrs_t *)bufP)->hdr.trMagic != LXTRACE_MAGIC) { DP("lxtrace: bad trace buffer from tracedev!\n"); DP("lxtrace: bufP 0x%X %d bytes at offset %d data 0x%X\n", bufP, nBytes, currentPos, ((trc_hdrs_t *)bufP)->hdr.trMagic); } else { #ifdef LXTRACE_USE_DIO /* dio nees 4k aligned buffers */ int totalBytes = nBytes + wrapBytes; int aioBytes = totalBytes & 0xfffff000; int extraBytes = totalBytes - aioBytes; DFP("trace daemon writing %d bytes at offset %d, wb %d, ab %d eb %d\n", totalBytes, currentPos, wrapBytes, aioBytes, extraBytes); if (aioBytes > 0) { /* Write the buffer to the trace output file */ memcpy(aiobufP[numBuf], wrapBuf, wrapBytes); memcpy((aiobufP[numBuf] + wrapBytes), bufP, aioBytes - wrapBytes); aioWrite(aiobufP[numBuf], aioBytes); if(extraBytes > 0) memcpy(wrapBuf, bufP + aioBytes - wrapBytes, extraBytes); wrapBytes = extraBytes; } else { /* Add data to the existing wrapBuf. There must be room, or * we wouldn't be here. */ DFP("trace daemon adding %d bytes to wrapBuf\n", nBytes); memcpy(wrapBuf + wrapBytes, bufP, nBytes); wrapBytes += nBytes; } currentPos += aioBytes; #else /* Write the buffer to the trace output file */ DFP("trace daemon writing %d bytes at offset %d\n", nBytes, currentPos); rc = write(out_fd, bufP, nBytes); currentPos += nBytes; #endif } goto retry; } } /* The daemon signal handler. This is the main part of the daemon which (after initializing) does nothing except wait for signals. SIGIO indicates that a trace buffer is ready to be processed, any other signal stops tracing and terminates the daemon. */ void SignalHandler(int signum) { int rc; struct kArgs args; DFP("trace daemon got signal %d\n", signum); switch (signum) { case SIGIO: /* This is the main daemon function. Handle SIGIO signals from the device and transfer the data from the device to the output file when received. */ ProcessBuffer(); break; default: /* SIGTERM (or other) will terminate the daemon and end the trace. */ // DP("trace daemon: terminating due to signal %d\n", signum); if (TraceHandle > 0) { /* Get any records that are buffered in the device. */ ProcessBuffer(); #ifdef LXTRACE_USE_DIO for (numBuf=0; numBuf < MAXAIOBUFS ; numBuf++) aioWait(numBuf); numBuf=0; rc = fcntl(out_fd,F_SETFL,0); rc = lseek(out_fd, currentPos, SEEK_SET); rc = write(out_fd, wrapBuf, wrapBytes); if(fileEnd) { lseek(out_fd, 0, SEEK_SET); ftruncate(out_fd, fileEnd); } for (numBuf=0; numBuf < MAXAIOBUFS ; numBuf++) if (wbufP[numBuf]) { free(wbufP[numBuf]); wbufP[numBuf]=NULL; } numBuf=0; #endif if (nWraps) DP("lxtrace: Trace file wrapped %d times.\n", nWraps); /* close everything */ close(TraceHandle); close(out_fd); } /* daemon terminates */ if (bufP) free(bufP); _exit(0); } } /* Print command syntax and exit */ void Usage() { DP("\n\ Usage: lxtrace { on on-args | off | format format-args | dump | fsync }\n\ \n\ Command line format for lxtrace on:\n\ lxtrace on [trcFile [filesize [bufsize]]]\n\ trcFile Name of raw trace file to be created. Default is\n\ /tmp/lxtrace.trc.\n\ filesize Optional maximum size of wrap-around trace file. A value\n\ of 0 means that the trace file grows indefinitely. Default\n\ is 16M.\n\ bufsize Optional size of each buffer. Default is 64K.\n\ \n\ Command line format for lxtrace format:\n\ lxtrace format [-T] [-v] [-t formatFile] [-w wobble] [-o outFile] [trcFile]\n\ -T Display timestamps as seconds since 1/1/1970. Default\n\ is to display the first timestamp as 0.0 and other\n\ timestamps as elapsed time since the first trace record.\n\ -v Verbose mode. Include CPU number, buffer number, and hook\n\ word in trace output. Default is to not include these.\n\ wobble Number of microseconds wobble allowed in timestamps.\n\ An apparent wrap within the wobble limit will be ignored.\n\ formatFile Name of file containing trace formats. Default is\n\ /usr/lpp/mmfs/mmfs.trcfmt.\n\ outFile Name of file to receive formatted trace output. Default\n\ is standard output.\n\ trcFile Name of input raw trace file. Default is /tmp/lxtrace.trc.\n"); if (TraceHandle != -1) close(TraceHandle); exit(1); } /* The lxtrace command. */ int main(int argc, char *argv[]) { int rc = 0; struct kArgs args; // command arguments int i; int nTrcHdrs; if (argc < 2) Usage(); /* A new trace is being started. Validate the options, open the files, start the daemon and configure the device. */ if (strcmp(argv[1], "on") == 0) { int hw, dpid; struct sigaction action; char* trcFileNameP; /* Initialize local state fields. */ out_fd = -1; bufP = NULL; outSize = DEF_TRC_FILESIZE; bufSize = DEF_TRC_BUFSIZE & 0xfffff000; currentPos = 0; nWraps = 0; /* Get output file name */ if (argc >= 3) trcFileNameP = argv[2]; else trcFileNameP = "/tmp/lxtrace.trc"; /* Special cases of specifying stdout or stderr to receive the trace output. */ if (strcmp(trcFileNameP, "stdout") == 0) out_fd = 1; //stdout; else if (strcmp(trcFileNameP, "stderr") == 0) out_fd = 2; //stderr; else { /* Open and trunc the output file. */ if (0 > (out_fd = open(trcFileNameP, O_RDWR|O_CREAT|O_TRUNC, 0644))) { DP("lxtrace on: could not open file %s, errno %d\n", trcFileNameP, errno); rc = errno; goto exit_on; } } #ifdef LXTRACE_USE_DIO rc=fcntl(out_fd,F_SETFL,O_DIRECT); #endif /* Save the output filesize. If the size is explicitly given as zero, do not wrap. */ if (argc >= 4) { outSize = atoi(argv[3]); if (((outSize < MIN_TRC_FILESIZE) || (outSize > MAX_TRC_FILESIZE)) && (outSize != 0)) { DP("Output file size must be 0 or between %d and %d\n", MIN_TRC_FILESIZE, MAX_TRC_FILESIZE); Usage(); } } /* If specified, set the trace device buffer size (otherwise use default) */ if (argc >= 5) { bufSize = atoi(argv[4]) & 0xfffff000; if ((bufSize < MIN_TRC_BUFSIZE) || (bufSize > MAX_TRC_BUFSIZE)) { DP("Buffer size must be between %d and %d\n", MIN_TRC_BUFSIZE, MAX_TRC_BUFSIZE); Usage(); } } /* The output filesize must be at least as big as the selected buffer size. */ if ((outSize != 0) && (outSize < bufSize)) { DP("lxtrace: the filesize (%d) must be at least as large as the bufsize (%d)\n", outSize, bufSize); Usage(); } /* The trace daemon does all the work. It is created here ("lxtrace on") and lives until "trace off" sends it a SIGTERM signal. */ dpid = fork(); if (dpid < 0) { DP("lxtrace on: unable to fork trace daemon"); rc = EAGAIN; goto exit; } else if (dpid != 0) { /* Parent */ return(0); /* parent's work is done. */ } else { /* Child/Daemon */ /* At this point, we are in the trace daemon. Complete device configuration and then wait on its signals. */ if (!(bufP = (char *)malloc(bufSize))) { DP("trace daemon: unable to malloc trace buffer"); rc = ENOMEM; goto exit_on; } memset(bufP, 0, bufSize); /* Force page faults to occur now */ #ifdef LXTRACE_USE_DIO for (i=0; i < MAXAIOBUFS; i++) { /* dio needs 4k aligned buffers */ wbufP[i] = malloc(bufSize + 4095); if(wbufP[i] == NULL) { DP("trace daemon: unable to malloc trace buffer"); rc = ENOMEM; goto exit_on; } aiobufP[i] = (char*)ROUNDUP(wbufP[i], 4096); memset(aiobufP[i], 0, bufSize); /* Force page faults to occur now */ aioStarted[i] = 0; } #endif /* Initialize the signal handler */ action.sa_handler = SignalHandler; sigfillset(&action.sa_mask); /* block all signals while the handler is running */ action.sa_flags = 0; if ((sigaction(SIGIO , &action, NULL)) || (sigaction(SIGTERM, &action, NULL))) { DP("trace daemon: unable to create signal handler\n"); rc = EINVAL; goto exit_on; } /* Initialize the trace device */ TraceHandle = open(TRC_DEVICE, O_RDWR); if (TraceHandle < 0) { /* Device does not exist, wrong type, or already open, ... */ DP("trace daemon: device open failed with errno %d\n", errno); rc = ENODEV; goto exit_on; } /* Configure trace device buffer size. */ args.arg1 = bufSize; rc = ioctl(TraceHandle, trc_bufSize, &args); if (rc < 0) { DP("trace daemon: device buffer request failed with errno %d\n", errno); rc = ENOMEM; goto exit_on; } /* Mark as ready for tracing. */ rc = ioctl(TraceHandle, trc_begin, NULL); if (rc < 0) { DP("trace daemon: device begin failed with errno %d\n", errno); rc = ENODEV; goto exit_on; } /* wait here forever (until SIGTERM is handled and exits) */ while (1) { DFP("trace daemon about to wait\n"); pause(); } _exit(-1); } /* child/daemon */ exit_on: /* exit here for failures during daemon initialization. */ DFP("trace daemon exitting\n"); if (TraceHandle > 0) close(TraceHandle); } /* Stopping a previously activated trace by notifying to the device. */ else if (strcmp(argv[1], "off") == 0) { int fd; fd = open(TRC_DEVICE, O_RDONLY); if (fd < 0) { DP("lxtrace off: device open failed rc %d errno %d\n", fd, errno); rc = ENODEV; goto exit; } /* trc_end terminates tracing. */ args.arg1 = 0; rc = ioctl(fd, trc_end, &args); if (rc < 0) { DP("lxtrace off: device end failed with errno %d\n", errno); rc = EINVAL; goto exit_off; } exit_off: /* When we close here, the daemon will be signalled to terminate. */ close(fd); } /* Format the trace file. */ else if (strcmp(argv[1], "format") == 0) { FILE *raw_fp; /* raw trace data file */ FILE *fmt_fp; /* the application formatting file */ FILE *out_fp; /* output file */ Boolean hasWrapped; /* the raw trace file became full and wrapped */ struct timeval tzero = { 0, 0 }; trc_hdrs_t h; int useTOD = 0; /* true if -T option given */ int verbose = 0; /* true if -v option given */ char* formatFileNameP = "/usr/lpp/mmfs/mmfs.trcfmt"; char* outputFileNameP = NULL; char* rawTraceFileNameP = "/tmp/lxtrace.trc"; char *compP, *fmtP; unsigned int llmask; i2nSpec_t *i2nP; int nRecordsProcessed = 0; /* useful when running under gdb */ int i, id; Boolean msgHandler; char timeBufP[26]; /* timestamp in string format */ FILE *version_fp; /* work buffers */ char application_data[LXTRACE_MAX_DATA]; /* raw trace data */ /* Array of id2name substitutions to be made */ typedef struct { char s[TRC_MAX_ID2NAME]; } idname_t; idname_t id2nameP[LXTRACE_MAX_FORMAT_SUBS]; char fmtString[256]; /* Array of pointers to the args for the fprintf that formats the output */ argType argP[LXTRACE_MAX_FORMAT_SUBS]; raw_fp = fmt_fp = out_fp = NULL; formatFileP = NULL; fmtDescSpaceP = NULL; #if defined(__64BIT__) startTime = 9223372036854775807; #else startTime = 2147483647; #endif stopTime = 0; /* Parse arguments */ for (i = 2; i < argc ; i++) { if (strcmp(argv[i], "-T") == 0) useTOD = 1; else if (strcmp(argv[i], "-v") == 0) verbose = 1; else if (strcmp(argv[i], "-w") == 0 && i+1 (rc = fread(application_data, 1, h.hdr.trLength - sizeof(trc_datahdr_t), raw_fp))) { DP("lxtrace format: could not read data from %s at offset %d, rc %d errno %d\n", rawTraceFileNameP, ftell(raw_fp), rc, errno); rc = errno; goto exit_format; } DFP("read %d bytes of application trace data\n", rc); /* If this is the first trace record, consider this time zero, unless the -T option was specified */ if (tzero.tv_sec == 0 && !useTOD) tzero = h.hdr.trTime; /* Convert trace time to time since first trace record unless the -T option was specified */ if (!useTOD) { h.hdr.trTime.tv_sec -= tzero.tv_sec; if (h.hdr.trTime.tv_usec >= tzero.tv_usec) h.hdr.trTime.tv_usec -= tzero.tv_usec; else { h.hdr.trTime.tv_sec--; h.hdr.trTime.tv_usec += 1000000 - tzero.tv_usec; } } /* Get the formatting record for the trace record with this hookid */ if (0 != GetFormatRecord(fmt_fp, (int)(h.rec.trHook & 0x0000FFFF), &compP, &fmtP, &llmask, &i2nP)) { DP("lxtrace format: No formatting record found for hook %X\n", h.rec.trHook); fprintf(out_fp, "Unknown hook id 0x%08X\n", h.rec.trHook); } else { /* Found the formatting information for the current trace record. */ /* Write leading information before the formatted trace. */ if (verbose) fprintf(out_fp, fmtString, h.hdr.trTime.tv_sec, h.hdr.trTime.tv_usec, h.hdr.trProcess, h.hdr.trCPU, h.hdr.trBuf, h.rec.trHook, compP); else fprintf(out_fp, fmtString, h.hdr.trTime.tv_sec, h.hdr.trTime.tv_usec, h.hdr.trProcess, compP); DFP("format string: %s\n", fmtP); DFP("raw data: %X %X %X %X %X\n", TRC_ARG(0), TRC_ARG(1), TRC_ARG(2), TRC_ARG(3), TRC_ARG(4)); /* Format-specific processing. */ if (h.rec.trSPos == _TR_FORMAT_I) { /* Trace data consists of n integer values */ for (i=0; i < h.rec.trNArgs; i++) argP[i] = TRC_ARG(i); } else if (h.rec.trSPos < LXTRACE_MAX_FORMAT_SUBS) { /* Trace data contains null terminated string at TRC_ARG(rec.trSPos); the length of the string is given by rec.trSLen (rounded up to a multiple of ARGLEN). Get a pointer to the string, make sure it's null-terminated (so we don't blow up if the trace data is trash), and compute how many extra TRC_ARG words are occupied by the string. */ // ?? should validate trSLen! char *s = (char *)&TRC_ARG(h.rec.trSPos); int xi = h.rec.trSLen/ARGLEN - 1; s[h.rec.trSLen - 1] = '\0'; for (i = 0; i < h.rec.trSPos; i++) argP[i] = TRC_ARG(i); argP[i++] = (argType)s; for (; i <= h.rec.trNArgs; i++) argP[i] = TRC_ARG(i + xi); } else if (h.rec.trSPos == _TR_FORMAT_F) { /* First n words are integer values; a double value is stored at TRC_ARG(rec.trNArgs) */ double *d = (double *)&TRC_ARG(h.rec.trNArgs); for (i = 0; i < h.rec.trNArgs; i++) argP[i] = TRC_ARG(i); memcpy(&argP[i], d, sizeof(double)); } else if (h.rec.trSPos == _TR_FORMAT_X) { /* XTrace type (preformatted) record. */ fputs(application_data, out_fp); i = strlen(application_data); if (i == 0 || application_data[i-1] != '\n') putc('\n', out_fp); continue; } else { DP("lxtrace format: format %d not supported\n", h.rec.trSPos); fprintf(out_fp, "Unsupported format %d\n", h.rec.trSPos); goto exit_format; } #if defined(GPFS_LITTLE_ENDIAN) && !defined(__64BIT__) /* On a 32 bit machine, 64 bit values are stored with the high-order word first, followed by the low-order word. The problem is that the reverse is expected by printf formatting. For each "%ll" in the formatting string, swap the words in the argP array so that the words are swapped into the expected order. The llmask bitvector indicates which arguments are of the %ll form. */ if (llmask) { int tmp; int argPos = 0; DFP("\nlong long formatting: %s\n", fmtP); /* Loop through the bits in llmask */ while (llmask) { if (llmask & 1) { DFP("switching argP[%d] and argP[%d]\n", argPos, argPos+1); tmp = argP[argPos]; argP[argPos] = argP[argPos+1]; argP[argPos+1] = tmp; argPos += 1; /* account for the extra arg for this 2-word sub */ } argPos += 1; llmask >>= 1; } } #endif // GPFS_LITTLE_ENDIAN and NOT __64BIT__ #ifdef DBGASSERTS if (i2nP == NULL && (h.rec.trSPos==_TR_FORMAT_I || h.rec.trSPos==_TR_FORMAT_F) && strstr(fmtP, "%s")) { DP("lxtrace format: hook %X is %s format record containing a string specification.\n", (h.rec.trHook&0x0000FFFF), (h.rec.trSPos==_TR_FORMAT_I) ? (char *) "an integer" : (h.rec.trSPos==_TR_FORMAT_F)? (char *) "a float": (char *) "an unknown"); DP(" The formatting information for this record does not provide any substitutions.\n"); fprintf(out_fp, "%s\n", fmtP); goto exit_format; } #endif // DBGASSERTS /* Update the argP[] array as necessary to do the substitutions */ if (i2nP != NULL) { /* This loop proceses each of the substitution strings */ for (i = 0; i2nP[i].i2nNameP != NULL; i++) { int whichSub = i2nP[i].argNum - 1; char *argtP = i2nP[i].i2nNameP; id = argP[whichSub]; /* Thread_id2name conversion need special treatment */ msgHandler = false; if (strcmp(argtP, "Thread_id2name") == 0) { /* Thread IDs >= FirstMsgHandlerThread are really message handler IDs, so look for a tscMsg_id2name entry in that case. Thread IDs < FirstMsgHandlerThread are "standard" thread IDs, so look for StdThread_id2name in that case. */ if (id >= FirstMsgHandlerThread) { /* Adjust id value and conversion function. Set a flag to remember to insert "Msg handler" in front of the name that is found. */ id -= FirstMsgHandlerThread; argtP = "tscMsg_id2name"; msgHandler = true; } else argtP = "StdThread_id2name"; } /* Now look-up the substitution for argtP (xx_id2name) that is associated with the appropriate traced value (id). */ if (0 != GetID2NameRecord(fmt_fp, argtP, id, TRC_MAX_ID2NAME, id2nameP[whichSub].s)) { /* Unable to find the formatting (substitution) information */ /* ip addresses are formatted as such */ if ((0 == strcmp(argtP, "nodeaddr_id2name")) || (0 == strcmp(argtP, "ipaddr_id2name")) ) { union { int i; unsigned char c[4]; } a; a.i = id; sprintf(id2nameP[whichSub].s, "%u.%u.%u.%u", a.c[0], a.c[1], a.c[2], a.c[3]); } /* lockState to string conversions. */ else if ((0 == strcmp(argtP, "lockstateHigh_id2name"))) { #define lsAcqPend 0x80000000 #define lsLxLock 0x40000000 #define lsXwLock 0x20000000 #define lsWaLock 0x10000000 #define lsWwLock 0x08000000 #define lsRvkLock 0x04000000 #define lsRoCount 0x003FF800 #define lsRoUnit 0x00000800 #define lsWoCount 0x000007FF #define lsWoUnit 0x00000001 char buf1[32], buf2[32]; buf1[0]='\0'; buf2[0]='\0'; if (id & lsRoCount) sprintf(buf1, " ro:%d", (id & lsRoCount)/lsRoUnit); if (id & lsWoCount) sprintf(buf2, " wo:%d", (id & lsWoCount)/lsWoUnit); sprintf(id2nameP[whichSub].s, "[%s%s%s%s%s%s%s%s", (id & lsAcqPend) ? " acq" : "", (id & lsLxLock) ? " lx" : "", (id & lsXwLock) ? " xw" : "", (id & lsWaLock) ? " wa" : "", (id & lsWwLock) ? " ww" : "", (id & lsRvkLock) ? " rvk" : "", buf1, buf2); } /* lockState to string conversions. */ else if ((0 == strcmp(argtP, "lockstateLow_id2name"))) { #define lsRfCount 0x7FF00000 #define lsRfUnit 0x00100000 #define lsWfCount 0x000FFE00 #define lsWfUnit 0x00000200 #define lsRsCount 0x000001FF #define lsRsUnit 0x00000001 char buf1[32], buf2[32], buf3[32]; buf1[0]='\0'; buf2[0]='\0'; buf3[0]='\0'; if (id & lsRfCount) sprintf(buf1, " rf:%d", (id & lsRfCount)/lsRfUnit); if (id & lsWfCount) sprintf(buf2, " wf:%d", (id & lsWfCount)/lsWfUnit); if (id & lsRsCount) sprintf(buf3, " rs:%d", (id & lsRoCount)/lsRoUnit); sprintf(id2nameP[whichSub].s, "%s%s%s ]", buf1, buf2, buf3); } /* lockFlags to string conversions. */ else if ((0 == strcmp(argtP, "lockflags_id2name"))) { #define lfDaemonWriter 0x0001 #define lfRevokePending 0x0002 #define lfRevokeProcessing 0x0004 sprintf(id2nameP[whichSub].s, "[%s%s%s ]", (id & lfDaemonWriter) ? " dmn" : "", (id & lfRevokePending) ? " rvk" : "", (id & lfRevokeProcessing) ? " pro" : ""); } /* reason is optional so handle the resulting value of zero. */ else if ((0 == strcmp(argtP, "reason_id2name")) && (id == 0)) strcpy(id2nameP[whichSub].s, "no reason given"); /* Any other case is a lack of proper formatting information for the generated trace record. Insert "unknown" into the formatted output and continue. */ else { #ifdef DBGASSERTS DP("lxtrace format: %s substitution %d (value=%d) not found (used in hook %04X).\n", argtP, whichSub+1, argP[whichSub], (h.rec.trHook&0x0000FFFF)); // To debug one of these, exit here. // goto exit_format; #endif // DBGASSERTS sprintf(id2nameP[whichSub].s, "unknown(%d)", argP[whichSub]); } } /* If we are converting the thread ID of a message handler, insert "Msg handler" in front of the name. */ if (msgHandler) { char tmpBuff[TRC_MAX_ID2NAME]; strncpy(tmpBuff, id2nameP[whichSub].s, sizeof(tmpBuff)); snprintf(id2nameP[whichSub].s, TRC_MAX_ID2NAME, "Msg handler %s", tmpBuff); } /* Alter the TRC_ARGLIST for this substituted parameter */ argP[whichSub] = (argType)id2nameP[whichSub].s; } /* for each substitution string */ } /* End-substitutions */ /* Output the completed trace record */ #if !defined(GPFS_ARCH_POWER) || !defined(GPFS_LINUX) || defined(__64BIT__) fprintf(out_fp, fmtP, TRC_ARGLIST); #else /* On Linux 32-bit Power architecture (and maybe others?), the va_list calling convention does not allow passing a mixture of longs and long longs in successive memory words. If long longs are present, break up the format string at each "%" and print the arguments separately, using llmask to determine which ones are long long. */ if (llmask == 0) fprintf(out_fp, fmtP, TRC_ARGLIST); else { int n = 0, ll = llmask; unsigned long long bign; char *ptr, *newptr; char *newfmtP = malloc(strlen(fmtP) + 1); if (newfmtP == NULL) { DP("lxtrace format: unable to malloc format buffer"); rc = ENOMEM; goto exit_format; } ptr = fmtP; newptr = newfmtP; while (*ptr) { if (*ptr != '%') *newptr++ = *ptr++; else { do *newptr++ = *ptr++; while (*ptr && *ptr != '%'); *newptr = '\0'; if (ll & 1) { bign = ((unsigned long long) argP[n] << 32) + (unsigned long)argP[n+1]; fprintf(out_fp, newfmtP, bign); n += 2; } else { fprintf(out_fp, newfmtP, argP[n]); n++; } ll >>= 1; newptr = newfmtP; } } *newptr = '\0'; if (newptr != newfmtP) fprintf(out_fp, newfmtP); free(newfmtP); } #endif nRecordsProcessed += 1; } /* end processing this trace record */ } /* while there are more unformatted trace records to process */ if (hasWrapped) { do_wrap: rewind(raw_fp); /* On a wrapped file, need to go back to the top. */ hasWrapped = false; /* Clear this so we don't do this more than once. */ DFP("lxtrace format: done with wrap-point to EOF. Going back to record 0\n"); goto start_formatting; } rc = 0; exit_format: /* print hash lookup statistics */ DFP("Stats: hook lookup %6d check %7d (%.1f)\n", nHookLookup, nHookCheck, (double)nHookCheck/(double)nHookLookup); DFP(" i2n lookup %6d check %7d (%.1f) fail %d\n", nI2NLookup, nI2NCheck, (double)nI2NCheck/(double)nI2NLookup, nI2NFail); DFP("Wrap point: %d.%06d-%d.%06d (delta %d.%06d)\n", wrap_prev.tv_sec, wrap_prev.tv_usec, wrap_next.tv_sec, wrap_next.tv_usec, (wrap_prev.tv_sec-wrap_next.tv_sec), (wrap_prev.tv_usec-wrap_next.tv_usec)); /* cleanup */ if (formatFileP) free(formatFileP); if (fmtDescSpaceP) free(fmtDescSpaceP); if (raw_fp != NULL) fclose(raw_fp); if (fmt_fp != NULL) fclose(fmt_fp); if (out_fp != NULL) fclose(out_fp); } /* "format" option */ /* Display the state information associated with the device. */ else if (strcmp(argv[1], "dump") == 0) { int fd; #define DUMP_LEN 512 char dumpBufP[DUMP_LEN]; fd = open(TRC_DEVICE, O_RDONLY); if (fd < 0) { DP("lxtrace dump: device open failed errno %d\n", errno); rc = ENODEV; goto exit; } /* Dump the trace device information */ args.arg1 = DUMP_LEN; args.arg2 = (long)dumpBufP; if (0 != (rc = ioctl(fd, trc_dump, &args))) { DP("lxtrace dump: device dump returns rc %d errno %d \n", rc, errno); } else { printf("%s\n", dumpBufP); } exit_dump: close(fd); } /* Flush any data that is currently buffered in the device. */ else if (strcmp(argv[1], "fsync") == 0) { int fd; fd = open(TRC_DEVICE, O_RDONLY); if (fd < 0) { DP("lxtrace fsync: device open failed with errno %d\n", errno); rc = ENODEV; goto exit; } if (0 != (rc = fsync(fd))) { DP("lxtrace fsync: device fsync returns rc %d errno %d\n", rc, errno); } exit_fsync: close(fd); } else Usage(); exit: return rc; }