darshan-parser.c 35.4 KB
Newer Older
1
2
3
4
5
/*
 *  (C) 2009 by Argonne National Laboratory.
 *      See COPYRIGHT in top-level directory.
 */

6
7
8
9
10
11
12
13
#include <stdio.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#include <string.h>
#include <zlib.h>
#include <time.h>
14
#include <stdlib.h>
15
#include <getopt.h>
16
#include <assert.h>
17

18
#include "darshan-logutils.h"
19

20
#include "uthash-1.9.2/src/uthash.h"
21
22
23
24

/*
 * Options
 */
Philip Carns's avatar
Philip Carns committed
25
26
27
28
#define OPTION_BASE  (1 << 0)  /* darshan log fields */
#define OPTION_TOTAL (1 << 1)  /* aggregated fields */
#define OPTION_PERF  (1 << 2)  /* derived performance */
#define OPTION_FILE  (1 << 3)  /* file count totals */
29
#define OPTION_RED_READ  (1 << 4)  /* files with redundant read traffic */
30
#define OPTION_META_RATIO  (1 << 5)  /* metadata time ratio */
31
#define OPTION_SHARED_SMALL_WRITES (1 << 6) /* shared files with small writes */
32
#define OPTION_SUMMARY (1 << 7) /* summary information */
33
34
35
36
#define OPTION_ALL (\
  OPTION_BASE|\
  OPTION_TOTAL|\
  OPTION_PERF|\
37
  OPTION_FILE|\
38
  OPTION_META_RATIO|\
39
  OPTION_SHARED_SMALL_WRITES|\
40
  OPTION_SUMMARY|\
41
  OPTION_RED_READ)
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78

#define FILETYPE_SHARED (1 << 0)
#define FILETYPE_UNIQUE (1 << 1)
#define FILETYPE_PARTSHARED (1 << 2)

#define max(a,b) (((a) > (b)) ? (a) : (b))
#define max3(a,b,c) (((a) > (b)) ? (((a) > (c)) ? (a) : (c)) : (((b) > (c)) ? (b) : (c)))

/*
 * Datatypes
 */
typedef struct hash_entry_s
{
    UT_hash_handle hlink;
    int64_t hash;
    int64_t type;
    int64_t procs;
    int64_t counters[CP_NUM_INDICES];
    double  fcounters[CP_F_NUM_INDICES];
    double cumul_time;
    double meta_time;
} hash_entry_t;

typedef struct perf_data_s
{
    int64_t total_bytes;
    double slowest_rank_time;
    double slowest_rank_meta_time;
    double shared_time_by_cumul;
    double shared_time_by_open;
    double shared_time_by_open_lastio;
    double shared_time_by_slowest;
    double shared_meta_time;
    double agg_perf_by_cumul;
    double agg_perf_by_open;
    double agg_perf_by_open_lastio;
    double agg_perf_by_slowest;
79
80
    double *rank_cumul_io_time;
    double *rank_cumul_md_time;
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
} perf_data_t;

typedef struct file_data_s
{
    int64_t total;
    int64_t total_size;
    int64_t total_max;
    int64_t read_only;
    int64_t read_only_size;
    int64_t read_only_max;
    int64_t write_only;
    int64_t write_only_size;
    int64_t write_only_max;
    int64_t read_write;
    int64_t read_write_size;
    int64_t read_write_max;
    int64_t unique;
    int64_t unique_size;
    int64_t unique_max;
    int64_t shared;
    int64_t shared_size;
    int64_t shared_max;
} file_data_t;

/*
 * Prototypes
 */
void accum_perf(struct darshan_file *, hash_entry_t *, perf_data_t *);
void calc_perf(struct darshan_job *, hash_entry_t *, perf_data_t *);

void accum_file(struct darshan_file *, hash_entry_t *, file_data_t *);
void calc_file(struct darshan_job *, hash_entry_t *, file_data_t *);
113
114
static void calc_red_read(struct darshan_job *djob,
               hash_entry_t *file_hash);
115
116
static void calc_shared_small_writes(struct darshan_job *djob,
               hash_entry_t *file_hash);
117
118
119
120
121
122
123
124
125

int usage (char *exename)
{
    fprintf(stderr, "Usage: %s [options] <filename>\n", exename);
    fprintf(stderr, "    --all   : all sub-options are enabled\n");
    fprintf(stderr, "    --base  : darshan log field data [default]\n");
    fprintf(stderr, "    --file  : total file counts\n");
    fprintf(stderr, "    --perf  : derived perf data\n");
    fprintf(stderr, "    --total : aggregated darshan field data\n");
126
    fprintf(stderr, "    --red-read : files with redundant read traffic\n");
127
    fprintf(stderr, "    --meta-ratio : ratio of I/O time spent in metadata\n");
128
    fprintf(stderr, "    --summary : summary information per job\n");
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143

    exit(1);
}

int parse_args (int argc, char **argv, char **filename)
{
    int index;
    int mask;
    static struct option long_opts[] =
    {
        {"all",   0, NULL, OPTION_ALL},
        {"base",  0, NULL, OPTION_BASE},
        {"file",  0, NULL, OPTION_FILE},
        {"perf",  0, NULL, OPTION_PERF},
        {"total", 0, NULL, OPTION_TOTAL},
144
        {"red-read", 0, NULL, OPTION_RED_READ},
145
        {"meta-ratio", 0, NULL, OPTION_META_RATIO},
146
        {"summary", 0, NULL, OPTION_SUMMARY},
147
        {"shared-small-writes", 0, NULL, OPTION_SHARED_SMALL_WRITES},
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
        {"help",  0, NULL, 0}
    };

    mask = 0;

    while(1)
    {
        int c = getopt_long(argc, argv, "", long_opts, &index);

        if (c == -1) break;

        switch(c)
        {
            case OPTION_ALL:
            case OPTION_BASE:
            case OPTION_FILE:
            case OPTION_PERF:
            case OPTION_TOTAL:
166
            case OPTION_RED_READ:
167
            case OPTION_META_RATIO:
168
            case OPTION_SHARED_SMALL_WRITES:
169
            case OPTION_SUMMARY:
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
                mask |= c;
                break;
            case 0:
            default:
                usage(argv[0]);
                break;
        }
    }

    if (optind < argc)
    {
        *filename = argv[optind];
    }
    else
    {
        usage(argv[0]);
    }

    /* default mask value if none specified */
    if (mask == 0)
    {
        mask = OPTION_BASE;
    }

    return mask;
}

197
198
199
int main(int argc, char **argv)
{
    int ret;
200
201
    int mask;
    char *filename;
202
203
204
205
    struct darshan_job job;
    struct darshan_file cp_file;
    char tmp_string[1024];
    time_t tmp_time = 0;
206
    darshan_fd file;
207
    int i;
208
    int mount_count;
209
    int64_t* devs;
210
211
    char** mnt_pts;
    char** fs_types;
212
    int last_rank = 0;
213
214
    char *token;
    char *save;
215
    char buffer[DARSHAN_JOB_METADATA_LEN];
216

217
218
219
220
221
222
223
224
225
226
227
    hash_entry_t *file_hash = NULL;
    hash_entry_t *curr = NULL;
    hash_entry_t *tmp = NULL;
    hash_entry_t total;
    perf_data_t pdata;
    file_data_t fdata;

    memset(&pdata, 0, sizeof(pdata));
    memset(&total, 0, sizeof(total));

    mask = parse_args(argc, argv, &filename);
228

229
    file = darshan_log_open(filename, "r");
230
231
    if(!file)
    {
232
        fprintf(stderr, "darshan_log_open() failed to open %s\n.", filename);
233
234
235
236
        return(-1);
    }
   
    /* read job info */
237
    ret = darshan_log_getjob(file, &job);
238
    if(ret < 0)
239
    {
240
        fprintf(stderr, "Error: unable to read job information from log file.\n");
241
        darshan_log_close(file);
242
243
244
        return(-1);
    }

245
246
247
    /* warn user about any missing information in this log format */
    darshan_log_print_version_warnings(&job);

248
    ret = darshan_log_getexe(file, tmp_string);
249
    if(ret < 0)
250
    {
251
        fprintf(stderr, "Error: unable to read trailing job information.\n");
252
        darshan_log_close(file);
253
254
255
        return(-1);
    }

256
    /* print job summary */
257
    printf("# darshan log version: %s\n", job.version_string);
258
259
    printf("# size of file statistics: %zu bytes\n", sizeof(cp_file));
    printf("# size of job statistics: %zu bytes\n", sizeof(job));
260
    printf("# exe: %s\n", tmp_string);
Philip Carns's avatar
Philip Carns committed
261
262
263
    printf("# uid: %" PRId64 "\n", job.uid);
    printf("# jobid: %" PRId64 "\n", job.jobid);
    printf("# start_time: %" PRId64 "\n", job.start_time);
264
    tmp_time += job.start_time;
265
    printf("# start_time_asci: %s", ctime(&tmp_time));
Philip Carns's avatar
Philip Carns committed
266
    printf("# end_time: %" PRId64 "\n", job.end_time);
267
268
    tmp_time = 0;
    tmp_time += job.end_time;
269
    printf("# end_time_asci: %s", ctime(&tmp_time));
Philip Carns's avatar
Philip Carns committed
270
271
    printf("# nprocs: %" PRId64 "\n", job.nprocs);
    printf("# run time: %" PRId64 "\n", job.end_time - job.start_time + 1);
272
273
274
275
276
    for(token=strtok_r(job.metadata, "\n", &save);
        token != NULL;
        token=strtok_r(NULL, "\n", &save))
    {
        char *key;
277
278
279
280
281
282
283
284
285
286
287
288
289
290
        char *value;
        /* NOTE: we intentionally only split on the first = character.
         * There may be additional = characters in the value portion
         * (for example, when storing mpi-io hints).
         */
        strcpy(buffer, token);
        key = buffer;
        value = index(buffer, '=');
        if(!value)
            continue;
        /* convert = to a null terminator to split key and value */
        value[0] = '\0';
        value++;
        printf("# metadata: %s = %s\n", key, value);
291
    }
292
293
 
    /* print table of mounted file systems */
294
    ret = darshan_log_getmounts(file, &devs, &mnt_pts, &fs_types, &mount_count);
295
    printf("\n# mounted file systems (device, mount point, and fs type)\n");
296
297
298
    printf("# -------------------------------------------------------\n");
    for(i=0; i<mount_count; i++)
    {
Philip Carns's avatar
Philip Carns committed
299
        printf("# mount entry: %" PRId64 "\t%s\t%s\n", devs[i], mnt_pts[i], fs_types[i]);
300
301
    }
  
302
303
304
305
306
307
308
309
310
    /* try to retrieve first record (may not exist) */
    ret = darshan_log_getfile(file, &job, &cp_file);
    if(ret < 0)
    {
        fprintf(stderr, "Error: failed to parse log file.\n");
        fflush(stderr);
        return(-1);
    }
    if(ret == 0)
311
312
313
    {
        /* it looks like the app didn't open any files */
        printf("# no files opened.\n");
314
        darshan_log_close(file);
315
316
317
        return(0);
    }

318
319
320
321
322
323
324
325
326
    if ((mask & OPTION_BASE))
    {
        printf("\n# description of columns:\n");
        printf("#   <rank>: MPI rank.  -1 indicates that the file is shared\n");
        printf("#      across all processes and statistics are aggregated.\n");
        printf("#   <file>: hash of file path.  0 indicates that statistics\n");
        printf("#      are condensed to refer to all files opened at the given\n");
        printf("#      process.\n");
        printf("#   <counter> and <value>: statistical counters.\n");
327
328
        printf("#      A value of -1 indicates that Darshan could not monitor\n");
        printf("#      that counter, and its value should be ignored.\n");
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
        printf("#   <name suffix>: last %d characters of file name.\n", CP_NAME_SUFFIX_LEN);
        printf("#   <mount pt>: mount point that the file resides on.\n");
        printf("#   <fs type>: type of file system that the file resides on.\n");
        printf("\n# description of counters:\n");
        printf("#   CP_POSIX_*: posix operation counts.\n");
        printf("#   CP_COLL_*: MPI collective operation counts.\n");
        printf("#   CP_INDEP_*: MPI independent operation counts.\n");
        printf("#   CP_SPIT_*: MPI split collective operation counts.\n");
        printf("#   CP_NB_*: MPI non blocking operation counts.\n");
        printf("#   READS,WRITES,OPENS,SEEKS,STATS, and MMAPS are types of operations.\n");
        printf("#   CP_*_NC_OPENS: number of indep. and collective pnetcdf opens.\n");
        printf("#   CP_HDF5_OPENS: number of hdf5 opens.\n");
        printf("#   CP_COMBINER_*: combiner counts for MPI mem and file datatypes.\n");
        printf("#   CP_HINTS: number of times MPI hints were used.\n");
        printf("#   CP_VIEWS: number of times MPI file views were used.\n");
        printf("#   CP_MODE: mode that file was opened in.\n");
        printf("#   CP_BYTES_*: total bytes read and written.\n");
        printf("#   CP_MAX_BYTE_*: highest offset byte read and written.\n");
        printf("#   CP_CONSEC_*: number of exactly adjacent reads and writes.\n");
        printf("#   CP_SEQ_*: number of reads and writes from increasing offsets.\n");
        printf("#   CP_RW_SWITCHES: number of times access alternated between read and write.\n");
        printf("#   CP_*_ALIGNMENT: memory and file alignment.\n");
        printf("#   CP_*_NOT_ALIGNED: number of reads and writes that were not aligned.\n");
        printf("#   CP_MAX_*_TIME_SIZE: size of the slowest read and write operations.\n");
        printf("#   CP_SIZE_READ_*: histogram of read access sizes.\n");
        printf("#   CP_SIZE_READ_AGG_*: histogram of MPI datatype total sizes.\n");
        printf("#   CP_EXTENT_READ_*: histogram of MPI datatype extents.\n");
        printf("#   CP_STRIDE*_STRIDE: the four most common strides detected.\n");
        printf("#   CP_STRIDE*_COUNT: count of the four most common strides.\n");
        printf("#   CP_ACCESS*_ACCESS: the four most common access sizes.\n");
        printf("#   CP_ACCESS*_COUNT: count of the four most common access sizes.\n");
        printf("#   CP_DEVICE: device id reported by stat().\n");
        printf("#   CP_SIZE_AT_OPEN: size of file when first opened.\n");
        printf("#   CP_*_RANK_BYTES: fastest, slowest and variance of bytes transfer.\n");
        printf("#   CP_F_OPEN_TIMESTAMP: timestamp of first open (mpi or posix).\n");
        printf("#   CP_F_*_START_TIMESTAMP: timestamp of first read/write (mpi or posix).\n");
        printf("#   CP_F_*_END_TIMESTAMP: timestamp of last read/write (mpi or posix).\n");
        printf("#   CP_F_CLOSE_TIMESTAMP: timestamp of last close (mpi or posix).\n");
        printf("#   CP_F_POSIX_READ/WRITE_TIME: cumulative time spent in posix reads or writes.\n");
        printf("#   CP_F_MPI_READ/WRITE_TIME: cumulative time spent in mpi-io reads or writes.\n");
        printf("#   CP_F_POSIX_META_TIME: cumulative time spent in posix open, close, fsync, stat and seek, .\n");
        printf("#   CP_F_MPI_META_TIME: cumulative time spent in mpi-io open, close, set_view, and sync.\n");
        printf("#   CP_MAX_*_TIME: duration of the slowest read and write operations.\n");
        printf("#   CP_*_RANK_TIME: fastest, slowest variance of transfer time.\n");

        printf("\n");
        CP_PRINT_HEADER();
    }
377

378
379
380
381
382
383
384
385
386
387
388
389
390
391
    pdata.rank_cumul_io_time = malloc(sizeof(double)*job.nprocs);
    pdata.rank_cumul_md_time = malloc(sizeof(double)*job.nprocs);
    if (!pdata.rank_cumul_io_time || !pdata.rank_cumul_md_time)
    {
        perror("malloc failed");
        darshan_log_close(file);
        return(-1);
    }
    else
    {
        memset(pdata.rank_cumul_io_time, 0, sizeof(double)*job.nprocs);
        memset(pdata.rank_cumul_md_time, 0, sizeof(double)*job.nprocs);
    }

392
    do
393
    {
394
395
        char* mnt_pt = NULL;
        char* fs_type = NULL;
396
        hash_entry_t *hfile = NULL;
397
398
399
400

        if(cp_file.rank != -1 && cp_file.rank < last_rank)
        {
            fprintf(stderr, "Error: log file contains out of order rank data.\n");
401
            fflush(stderr);
402
403
404
405
            return(-1);
        }
        if(cp_file.rank != -1)
            last_rank = cp_file.rank;
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
        
        for(i=0; i<mount_count; i++)
        {
            if(cp_file.counters[CP_DEVICE] == devs[i])
            {
                mnt_pt = mnt_pts[i];
                fs_type = fs_types[i];
                break;
            }
        }
        if(!mnt_pt)
            mnt_pt = "UNKNOWN";
        if(!fs_type)
            fs_type = "UNKNOWN";

421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
        HASH_FIND(hlink,file_hash,&cp_file.hash,sizeof(int64_t),hfile);
        if (!hfile)
        {
            hfile = (hash_entry_t*) malloc(sizeof(*hfile));
            if (!hfile)
            {
                fprintf(stderr,"malloc failure");
                exit(1);
            }

            /* init */
            memset(hfile, 0, sizeof(*hfile));
            hfile->hash          = cp_file.hash;
            hfile->type          = 0;
            hfile->procs         = 0;
            hfile->cumul_time    = 0.0;
            hfile->meta_time     = 0.0;

            HASH_ADD(hlink,file_hash,hash,sizeof(int64_t),hfile);
        }

        accum_file(&cp_file, &total, NULL);
        accum_file(&cp_file, hfile, &fdata);
        accum_perf(&cp_file, hfile, &pdata);

        if ((mask & OPTION_BASE))
        {
            for(i=0; i<CP_NUM_INDICES; i++)
            {
                CP_PRINT(&job, &cp_file, i, mnt_pt, fs_type);
            }
            for(i=0; i<CP_F_NUM_INDICES; i++)
            {
                CP_F_PRINT(&job, &cp_file, i, mnt_pt, fs_type);
            }
        }
457
    }while((ret = darshan_log_getfile(file, &job, &cp_file)) == 1);
458
459
460
461

    /* Total Calc */
    if ((mask & OPTION_TOTAL))
    {
462
463
        for(i=0; i<CP_NUM_INDICES; i++)
        {
Philip Carns's avatar
Philip Carns committed
464
            printf("total_%s: %" PRId64 "\n",
465
                   darshan_names[i], total.counters[i]);
466
467
468
        }
        for(i=0; i<CP_F_NUM_INDICES; i++)
        {
469
470
            printf("total_%s: %lf\n",
                   darshan_f_names[i], total.fcounters[i]);
471
        }
472
473
    }

474
475
476
477
478
479
    /* Perf Calc */
    calc_perf(&job, file_hash, &pdata);
    if ((mask & OPTION_PERF))
    {
        printf("\n# performance\n");
        printf("# -----------\n");
Philip Carns's avatar
Philip Carns committed
480
        printf("# total_bytes: %" PRId64 "\n", pdata.total_bytes);
481
482
483
484
485
486
487
488
489
490
491
        printf("# slowest_rank_time: %lf\n", pdata.slowest_rank_time);
        printf("# slowest_rank_meta_time: %lf\n", pdata.slowest_rank_meta_time);
        printf("# shared_time_by_cumul: %lf\n", pdata.shared_time_by_cumul);
        printf("# shared_time_by_open: %lf\n", pdata.shared_time_by_open);
        printf("# shared_time_by_open_lastio: %lf\n", pdata.shared_time_by_open_lastio);
        printf("# shared_meta_time: %lf\n", pdata.shared_meta_time);
        printf("# agg_perf_by_cumul: %lf\n", pdata.agg_perf_by_cumul);
        printf("# agg_perf_by_open: %lf\n", pdata.agg_perf_by_open);
        printf("# agg_perf_by_open_lastio: %lf\n", pdata.agg_perf_by_open_lastio);
        printf("# agg_perf_by_slowest: %lf\n", pdata.agg_perf_by_slowest);
    }
492
493
    if((mask & OPTION_META_RATIO))
    {
494
495
496
497
498
499
500
501
502
503
504
505
506
507
        double avg_io_time = 0;
        double avg_meta_time = 0;

        for(i=0; i<job.nprocs; i++)
        {
            avg_io_time += pdata.rank_cumul_io_time[i];
            avg_meta_time += pdata.rank_cumul_md_time[i];
        }
        avg_io_time /= (double)job.nprocs;
        avg_meta_time /= (double)job.nprocs;
        avg_io_time += pdata.shared_time_by_cumul;
        avg_meta_time += pdata.shared_meta_time / (double)job.nprocs;

        printf("#<jobid>\t<uid>\t<procs>\t<start>\t<type>\t<avg_io_time>\t<avg_meta_time>\t<percent>\n");
508
        printf("%" PRId64 "\t%" PRId64 "\t%" PRId64 "\t%" PRId64 "\tmeta-ratio\t%lf\t%lf\t%lf\n",
509
            job.jobid, job.uid, job.nprocs, job.start_time, avg_io_time, avg_meta_time, avg_meta_time/avg_io_time);
510
    }
511

512
513
514
515
516
517
    /* Redundant read calc */
    if((mask & OPTION_RED_READ))
    {
        calc_red_read(&job, file_hash);
    }

518
519
520
521
522
523
    /* shared small write call */
    if((mask & OPTION_SHARED_SMALL_WRITES))
    {
        calc_shared_small_writes(&job, file_hash);
    }

524
525
526
527
528
529
    /* File Calc */
    calc_file(&job, file_hash, &fdata);
    if ((mask & OPTION_FILE))
    {
        printf("\n# files\n");
        printf("# -----\n");
Philip Carns's avatar
Philip Carns committed
530
        printf("# total: %" PRId64 " %" PRId64 " %" PRId64 "\n",
531
532
533
               fdata.total,
               fdata.total_size,
               fdata.total_max);
Philip Carns's avatar
Philip Carns committed
534
        printf("# read_only: %" PRId64 " %" PRId64 " %" PRId64 "\n",
535
536
537
               fdata.read_only,
               fdata.read_only_size,
               fdata.read_only_max);
Philip Carns's avatar
Philip Carns committed
538
        printf("# write_only: %" PRId64 " %" PRId64 " %" PRId64 "\n",
539
540
541
               fdata.write_only,
               fdata.write_only_size,
               fdata.write_only_max);
Philip Carns's avatar
Philip Carns committed
542
        printf("# read_write: %" PRId64 " %" PRId64 " %" PRId64 "\n",
543
544
545
               fdata.read_write,
               fdata.read_write_size,
               fdata.read_write_max);
Philip Carns's avatar
Philip Carns committed
546
        printf("# unique: %" PRId64 " %" PRId64 " %" PRId64 "\n",
547
548
549
               fdata.unique,
               fdata.unique_size,
               fdata.unique_max);
Philip Carns's avatar
Philip Carns committed
550
        printf("# shared: %" PRId64 " %" PRId64 " %" PRId64 "\n",
551
552
553
               fdata.shared,
               fdata.shared_size,
               fdata.shared_max);
554
555
    }

Philip Carns's avatar
Philip Carns committed
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
    if((mask & OPTION_SUMMARY))
    {
        double avg_io_time = 0;
        double slowest = 0;
        if(pdata.shared_time_by_slowest)
                slowest = pdata.shared_time_by_slowest;
        else
                slowest = pdata.shared_time_by_open_lastio;

        slowest += pdata.slowest_rank_time;

        for(i=0; i<job.nprocs; i++)
        {
            avg_io_time += pdata.rank_cumul_io_time[i];
        }
        avg_io_time /= (double)job.nprocs;
        avg_io_time += pdata.shared_time_by_cumul;

        printf("#<jobid>\t<uid>\t<procs>\t<start>\t<end>\t<type>\t<slowest_proc_io_time>\t<bytes_read>\t<bytes_written>\t<total files opened>\t<read histos 10x...>\t<write histos 10x...\n");
        printf("%" PRId64 "\t%" PRId64 "\t%" PRId64 "\t%" PRId64 "\t%" PRId64 "\tsummary\t%lf\t%" PRId64 "\t%" PRId64 "\t%" PRId64,
            job.jobid, job.uid, job.nprocs, job.start_time, job.end_time, slowest, total.counters[CP_BYTES_READ], total.counters[CP_BYTES_WRITTEN], fdata.total);
        for(i=CP_SIZE_READ_0_100; i<=CP_SIZE_WRITE_1G_PLUS; i++)
        {
            printf("\t%" PRId64, total.counters[i]);
        }
        printf("\n");
    }


585
    if(ret < 0)
586
    {
587
        fprintf(stderr, "Error: failed to parse log file.\n");
588
        fflush(stderr);
589
590
591
        return(-1);
    }

592
593
594
595
596
    for(i=0; i<mount_count; i++)
    {
        free(mnt_pts[i]);
        free(fs_types[i]);
    }
597
598
599
600
601
602
    if(mount_count > 0)
    {
        free(devs);
        free(mnt_pts);
        free(fs_types);
    }
603
 
604
    darshan_log_close(file);
605
606
607
608
609
610
611

    HASH_ITER(hlink, file_hash, curr, tmp)
    {
        HASH_DELETE(hlink, file_hash, curr);
        free(curr);
    }

612
613
    return(0);
}
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644

void accum_file(struct darshan_file *dfile,
                hash_entry_t *hfile, 
                file_data_t *fdata)
{
    int i;

    hfile->procs += 1;

    if (dfile->rank == -1)
    {
        hfile->type |= FILETYPE_SHARED;
    }
    else if (hfile->procs > 1)
    {
        hfile->type &= (~FILETYPE_UNIQUE);
        hfile->type |= FILETYPE_PARTSHARED;
    }
    else
    {
        hfile->type |= FILETYPE_UNIQUE;
    }

    for (i = 0; i < CP_NUM_INDICES; i++)
    {
        switch(i)
        {
        case CP_DEVICE:
        case CP_MODE:
        case CP_MEM_ALIGNMENT:
        case CP_FILE_ALIGNMENT:
645
646
            if(CP_FILE_PARTIAL(hfile))
                hfile->counters[i] = dfile->counters[i];
647
648
649
650
651
652
            break;
        case CP_SIZE_AT_OPEN:
            if (hfile->counters[i] == -1)
            {
                hfile->counters[i] = dfile->counters[i];
            }
653
            if (hfile->counters[i] > dfile->counters[i] && !CP_FILE_PARTIAL(dfile))
654
655
656
657
658
659
660
661
662
663
664
            {
                hfile->counters[i] = dfile->counters[i];
            }
            break;
        case CP_MAX_BYTE_READ:
        case CP_MAX_BYTE_WRITTEN:
            if (hfile->counters[i] < dfile->counters[i])
            {
                hfile->counters[i] = dfile->counters[i];
            }
            break;
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679

        case CP_STRIDE1_STRIDE:
        case CP_STRIDE2_STRIDE:
        case CP_STRIDE3_STRIDE:
        case CP_STRIDE4_STRIDE:
        case CP_ACCESS1_ACCESS:
        case CP_ACCESS2_ACCESS:
        case CP_ACCESS3_ACCESS:
        case CP_ACCESS4_ACCESS:
           /*
            * do nothing here because these will be stored
            * when the _COUNT is accessed.
            */
           break;
 
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
        case CP_STRIDE1_COUNT:
        case CP_STRIDE2_COUNT:
        case CP_STRIDE3_COUNT:
        case CP_STRIDE4_COUNT:
        case CP_ACCESS1_COUNT:
        case CP_ACCESS2_COUNT:
        case CP_ACCESS3_COUNT:
        case CP_ACCESS4_COUNT:
            if (hfile->counters[i] < dfile->counters[i])
            {
                hfile->counters[i]   = dfile->counters[i];
                hfile->counters[i-4] = dfile->counters[i-4];
            }
            break;
        case CP_FASTEST_RANK:
        case CP_SLOWEST_RANK:
        case CP_FASTEST_RANK_BYTES:
        case CP_SLOWEST_RANK_BYTES:
            hfile->counters[i] = 0;
            break;
        case CP_MAX_READ_TIME_SIZE:
        case CP_MAX_WRITE_TIME_SIZE:
            break;
        default:
            hfile->counters[i] += dfile->counters[i];
            break;
        }
    }

    for (i = 0; i < CP_F_NUM_INDICES; i++)
    {
        switch(i)
        {
            case CP_F_FASTEST_RANK_TIME:
            case CP_F_SLOWEST_RANK_TIME:
            case CP_F_VARIANCE_RANK_TIME:
            case CP_F_VARIANCE_RANK_BYTES:
                hfile->fcounters[i] = 0;
                break;
            case CP_F_MAX_READ_TIME:
                if (hfile->fcounters[i] > dfile->fcounters[i])
                {
                    hfile->fcounters[i] = dfile->fcounters[i];
                    hfile->counters[CP_MAX_READ_TIME_SIZE] =
                        dfile->counters[CP_MAX_READ_TIME_SIZE];
                }
                break;
            case CP_F_MAX_WRITE_TIME:
                if (hfile->fcounters[i] > dfile->fcounters[i])
                {
                    hfile->fcounters[i] = dfile->fcounters[i];
                    hfile->counters[CP_MAX_WRITE_TIME_SIZE] =
                        dfile->counters[CP_MAX_WRITE_TIME_SIZE];
                }
                break;
            default:
                hfile->fcounters[i] += dfile->fcounters[i];
                break;
        }
    }

    return;
}


745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
static void calc_shared_small_writes(struct darshan_job *djob,
               hash_entry_t *file_hash)
{
    hash_entry_t *curr = NULL;
    hash_entry_t *tmp = NULL;
    int header_print = 0;

    HASH_ITER(hlink, file_hash, curr, tmp)
    {
        int i;
        uint64_t writes_lt_100k = 0;
        uint64_t writes_gt_100k = 0;

        /* only look at shared files that were written to */
        if(curr->type == FILETYPE_SHARED && curr->counters[CP_BYTES_WRITTEN] > 0 && curr->counters[CP_COLL_WRITES] == 0)
        {
            if(!header_print)
            {
                printf("#<jobid>\t<uid>\t<procs>\t<start>\t<type>\t<writes_lt_100k>\t<writes_gt_100k>\t<bytes_written>\n");
                header_print = 1;
            }

            for(i=CP_SIZE_WRITE_0_100; i<= CP_SIZE_WRITE_10K_100K; i++)
                writes_lt_100k += curr->counters[i];
            for(i=CP_SIZE_WRITE_100K_1M; i<= CP_SIZE_WRITE_1G_PLUS; i++)
                writes_gt_100k += curr->counters[i];

            printf("%" PRId64 "\t%" PRId64 "\t%" PRId64 "\t%" PRId64 "\tshared-small-writes\t%" PRIu64 "\t%" PRIu64 "\t%" PRIu64 "\t%" PRIu64 "\n",
                djob->jobid, djob->uid, djob->nprocs, djob->start_time, curr->hash, 
                writes_lt_100k, writes_gt_100k, curr->counters[CP_BYTES_WRITTEN]);
        }
    }

    return;
}

781
782
783
784
785
static void calc_red_read(struct darshan_job *djob,
               hash_entry_t *file_hash)
{
    hash_entry_t *curr = NULL;
    hash_entry_t *tmp = NULL;
786
787
    uint64_t total_max = 0;
    uint64_t total_read = 0;
788
    int header_print = 0;
789
790
791
792
793

    HASH_ITER(hlink, file_hash, curr, tmp)
    {
        if((curr->counters[CP_MAX_BYTE_READ]+1) < curr->counters[CP_BYTES_READ])
        {
794
795
796
797
798
            if(!header_print)
            {
                printf("#<jobid>\t<uid>\t<procs>\t<start>\t<type>\t<file_hash>\t<max_byte_read>\t<bytes_read>\t<diff>\n");
                header_print = 1;
            }
799
800
            total_read += curr->counters[CP_BYTES_READ];
            total_max += (curr->counters[CP_MAX_BYTE_READ]+1);
801
802
            printf("%" PRId64 "\t%" PRId64 "\t%" PRId64 "\t%" PRId64 "\tred-read-file\t%" PRIu64 "\t%" PRIu64 "\t%" PRIu64 "\t%" PRIu64 "\n",
                djob->jobid, djob->uid, djob->nprocs, djob->start_time, curr->hash, curr->counters[CP_MAX_BYTE_READ], curr->counters[CP_BYTES_READ], curr->counters[CP_BYTES_READ] - (curr->counters[CP_MAX_BYTE_READ]+1));
803
804
805
        }
    }

806
807
    if(total_read > 0)
    {
808
809
        printf("%" PRId64 "\t%" PRId64 "\t%" PRId64 "\t%" PRId64 "\tred-read-summary\t%" PRIu64 "\t%" PRIu64 "\t%" PRIu64 "\t%" PRIu64 "\n",
            djob->jobid, djob->uid, djob->nprocs, djob->start_time, (int64_t)0, total_max, total_read, total_read-total_max);
810
811
    }

812
813
814
    return;
}

815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
void calc_file(struct darshan_job *djob,
               hash_entry_t *file_hash, 
               file_data_t *fdata)
{
    hash_entry_t *curr = NULL;
    hash_entry_t *tmp = NULL;

    memset(fdata, 0, sizeof(*fdata));

    HASH_ITER(hlink, file_hash, curr, tmp)
    {
        int64_t max;
        int64_t r;
        int64_t w;

        max = max3(curr->counters[CP_SIZE_AT_OPEN],
                   curr->counters[CP_MAX_BYTE_READ],
                   curr->counters[CP_MAX_BYTE_WRITTEN]);

        r = (curr->counters[CP_POSIX_READS]+
             curr->counters[CP_POSIX_FREADS]+
             curr->counters[CP_INDEP_READS]+
             curr->counters[CP_COLL_READS]+
             curr->counters[CP_SPLIT_READS]+
             curr->counters[CP_NB_READS]);

        w = (curr->counters[CP_POSIX_WRITES]+
             curr->counters[CP_POSIX_FWRITES]+
             curr->counters[CP_INDEP_WRITES]+
             curr->counters[CP_COLL_WRITES]+
             curr->counters[CP_SPLIT_WRITES]+
             curr->counters[CP_NB_WRITES]);

        fdata->total += 1;
        fdata->total_size += max;
        fdata->total_max = max(fdata->total_max, max);

        if (r && !w)
        {
            fdata->read_only += 1;
            fdata->read_only_size += max;
            fdata->read_only_max = max(fdata->read_only_max, max);
        }

        if (!r && w)
        {
            fdata->write_only += 1;
            fdata->write_only_size += max;
            fdata->write_only_max = max(fdata->write_only_max, max);
        }

        if (r && w)
        {
            fdata->read_write += 1;
            fdata->read_write_size += max;
            fdata->read_write_max = max(fdata->read_write_max, max);
        }

        if ((curr->type & (FILETYPE_SHARED|FILETYPE_PARTSHARED)))
        {
            fdata->shared += 1;
            fdata->shared_size += max;
            fdata->shared_max = max(fdata->shared_max, max);
        }

        if ((curr->type & (FILETYPE_UNIQUE)))
        {
            fdata->unique += 1;
            fdata->unique_size += max;
            fdata->unique_max = max(fdata->unique_max, max);
        }
    }

    return;
}

void accum_perf(struct darshan_file *dfile,
                hash_entry_t *hfile,
                perf_data_t *pdata)
{
    int64_t mpi_file;

    pdata->total_bytes += dfile->counters[CP_BYTES_READ] +
                          dfile->counters[CP_BYTES_WRITTEN];

    mpi_file = dfile->counters[CP_INDEP_OPENS] +
               dfile->counters[CP_COLL_OPENS];

    /*
     * Calculation of Shared File Time
     *   Four Methods!!!!
     *     by_cumul: sum time counters and divide by nprocs
     *               (inaccurate if lots of variance between procs)
     *     by_open: difference between timestamp of open and close
     *              (inaccurate if file is left open without i/o happening)
     *     by_open_lastio: difference between timestamp of open and the
     *                     timestamp of last i/o
     *                     (similar to above but fixes case where file is left
     *                      open after io is complete)
     *     by_slowest: use slowest rank time from log data
     *                 (most accurate but requires newer log version)
     */
    if (dfile->rank == -1)
    {
        /* by_open (same for MPI or POSIX) */
920
921
922
923
924
925
926
        if (dfile->fcounters[CP_F_CLOSE_TIMESTAMP] >
            dfile->fcounters[CP_F_OPEN_TIMESTAMP])
        {
            pdata->shared_time_by_open +=
                dfile->fcounters[CP_F_CLOSE_TIMESTAMP] -
                dfile->fcounters[CP_F_OPEN_TIMESTAMP];
        }
927
928
929
930
931

        /* by_open_lastio (same for MPI or POSIX) */
        if (dfile->fcounters[CP_F_READ_END_TIMESTAMP] >
            dfile->fcounters[CP_F_WRITE_END_TIMESTAMP])
        {
932
933
934
935
936
937
938
            /* be careful: file may have been opened but not read or written */
            if(dfile->fcounters[CP_F_READ_END_TIMESTAMP] > dfile->fcounters[CP_F_OPEN_TIMESTAMP])
            {
                pdata->shared_time_by_open_lastio += 
                    dfile->fcounters[CP_F_READ_END_TIMESTAMP] - 
                    dfile->fcounters[CP_F_OPEN_TIMESTAMP];
            }
939
940
941
        }
        else
        {
942
943
944
945
946
947
948
            /* be careful: file may have been opened but not read or written */
            if(dfile->fcounters[CP_F_WRITE_END_TIMESTAMP] > dfile->fcounters[CP_F_OPEN_TIMESTAMP])
            {
                pdata->shared_time_by_open_lastio += 
                    dfile->fcounters[CP_F_WRITE_END_TIMESTAMP] - 
                    dfile->fcounters[CP_F_OPEN_TIMESTAMP];
            }
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
        }

        /* by_cumul */
        if (mpi_file)
        {
            pdata->shared_time_by_cumul +=
                dfile->fcounters[CP_F_MPI_META_TIME] +
                dfile->fcounters[CP_F_MPI_READ_TIME] +
                dfile->fcounters[CP_F_MPI_WRITE_TIME];
            pdata->shared_meta_time += dfile->fcounters[CP_F_MPI_META_TIME];
        }
        else
        {
            pdata->shared_time_by_cumul +=
                dfile->fcounters[CP_F_POSIX_META_TIME] +
                dfile->fcounters[CP_F_POSIX_READ_TIME] +
                dfile->fcounters[CP_F_POSIX_WRITE_TIME];
            pdata->shared_meta_time += dfile->fcounters[CP_F_POSIX_META_TIME];
        }

        /* by_slowest (same for MPI or POSIX) */
        pdata->shared_time_by_slowest +=
            dfile->fcounters[CP_F_SLOWEST_RANK_TIME];
    }

    /*
     * Calculation of Unique File Time
     *   record the data for each file and sum it 
     */
    else
    {
        if (mpi_file)
        {
982
#if 0
983
984
985
986
            hfile->cumul_time += dfile->fcounters[CP_F_MPI_META_TIME] +
                                dfile->fcounters[CP_F_MPI_READ_TIME] +
                                dfile->fcounters[CP_F_MPI_WRITE_TIME];
            hfile->meta_time += dfile->fcounters[CP_F_MPI_META_TIME];
987
988
989
990
991
992
#else
            pdata->rank_cumul_io_time[dfile->rank] += dfile->fcounters[CP_F_MPI_META_TIME] +
                                dfile->fcounters[CP_F_MPI_READ_TIME] +
                                dfile->fcounters[CP_F_MPI_WRITE_TIME];
            pdata->rank_cumul_md_time[dfile->rank] += dfile->fcounters[CP_F_MPI_META_TIME];
#endif
993
994
995
        }
        else
        {
996
#if 0
997
998
999
1000
             hfile->cumul_time += dfile->fcounters[CP_F_POSIX_META_TIME] +
                                 dfile->fcounters[CP_F_POSIX_READ_TIME] +
                                 dfile->fcounters[CP_F_POSIX_WRITE_TIME];
             hfile->meta_time += dfile->fcounters[CP_F_POSIX_META_TIME];
1001
1002
1003
1004
1005
1006
1007
#else
            pdata->rank_cumul_io_time[dfile->rank] += dfile->fcounters[CP_F_POSIX_META_TIME] +
                                dfile->fcounters[CP_F_POSIX_READ_TIME] +
                                dfile->fcounters[CP_F_POSIX_WRITE_TIME];
            pdata->rank_cumul_md_time[dfile->rank] += dfile->fcounters[CP_F_POSIX_META_TIME];

#endif
1008
        }
1009

1010
#if 0
1011
1012
        pdata->rank_cumul_io_time[dfile->rank] += hfile->cumul_time;
        pdata->rank_cumul_md_time[dfile->rank] += hfile->meta_time;
1013
#endif
1014
1015
1016
1017
1018
1019
1020
1021
1022
    }

    return;
}

void calc_perf(struct darshan_job *djob,
               hash_entry_t *hash_rank_uniq,
               perf_data_t *pdata)
{
1023
    int64_t i;
1024
1025
1026
1027
1028
1029

    pdata->shared_time_by_cumul =
        pdata->shared_time_by_cumul / (double)djob->nprocs;

    pdata->shared_meta_time = pdata->shared_meta_time / (double)djob->nprocs;

1030
    for (i=0; i<djob->nprocs; i++)
1031
    {
1032
        if (pdata->rank_cumul_io_time[i] > pdata->slowest_rank_time)
1033
        {
1034
            pdata->slowest_rank_time = pdata->rank_cumul_io_time[i];
1035
            pdata->slowest_rank_meta_time = pdata->rank_cumul_md_time[i];
1036
1037
1038
        }
    }

1039
    if (pdata->slowest_rank_time + pdata->shared_time_by_cumul)
1040
    pdata->agg_perf_by_cumul = ((double)pdata->total_bytes / 1048576.0) /
1041
1042
1043
1044
                                  (pdata->slowest_rank_time +
                                   pdata->shared_time_by_cumul);

    if (pdata->slowest_rank_time + pdata->shared_time_by_open)
1045
    pdata->agg_perf_by_open  = ((double)pdata->total_bytes / 1048576.0) / 
1046
1047
1048
1049
                                   (pdata->slowest_rank_time +
                                    pdata->shared_time_by_open);

    if (pdata->slowest_rank_time + pdata->shared_time_by_open_lastio)
1050
1051
1052
    pdata->agg_perf_by_open_lastio = ((double)pdata->total_bytes / 1048576.0) /
                                     (pdata->slowest_rank_time +
                                      pdata->shared_time_by_open_lastio);
1053

1054
1055
    if (pdata->slowest_rank_time + pdata->shared_time_by_slowest)
    pdata->agg_perf_by_slowest = ((double)pdata->total_bytes / 1048576.0) /
1056
1057
                                     (pdata->slowest_rank_time +
                                      pdata->shared_time_by_slowest);
1058
1059
1060

    return;
}