fs/gfs2/trace_gfs2.h

   1 #undef TRACE_SYSTEM
   2 #define TRACE_SYSTEM gfs2
   3
   4 #if !defined(_TRACE_GFS2_H) || defined(TRACE_HEADER_MULTI_READ)
   5 #define _TRACE_GFS2_H
   6
   7 #include <linux/tracepoint.h>
   8
   9 #include <linux/fs.h>
  10 #include <linux/buffer_head.h>
  11 #include <linux/dlmconstants.h>
  12 #include <linux/gfs2_ondisk.h>
  13 #include <linux/writeback.h>
  14 #include <linux/ktime.h>
  15 #include "incore.h"
  16 #include "glock.h"
  17 #include "rgrp.h"
  18
  19 #define dlm_state_name(nn) { DLM_LOCK_##nn, #nn }
  20 #define glock_trace_name(x) __print_symbolic(x,         \
  21                             dlm_state_name(IV),         \
  22                             dlm_state_name(NL),         \
  23                             dlm_state_name(CR),         \
  24                             dlm_state_name(CW),         \
  25                             dlm_state_name(PR),         \
  26                             dlm_state_name(PW),         \
  27                             dlm_state_name(EX))
  28
  29 #define block_state_name(x) __print_symbolic(x,                 \
  30                             { GFS2_BLKST_FREE, "free" },        \
  31                             { GFS2_BLKST_USED, "used" },        \
  32                             { GFS2_BLKST_DINODE, "dinode" },    \
  33                             { GFS2_BLKST_UNLINKED, "unlinked" })
  34
  35 #define TRACE_RS_DELETE  0
  36 #define TRACE_RS_TREEDEL 1
  37 #define TRACE_RS_INSERT  2
  38 #define TRACE_RS_CLAIM   3
  39
  40 #define rs_func_name(x) __print_symbolic(x,     \
  41                                          { 0, "del " }, \
  42                                          { 1, "tdel" }, \
  43                                          { 2, "ins " }, \
  44                                          { 3, "clm " })
  45
  46 #define show_glock_flags(flags) __print_flags(flags, "",        \
  47         {(1UL << GLF_LOCK),                     "l" },          \
  48         {(1UL << GLF_DEMOTE),                   "D" },          \
  49         {(1UL << GLF_PENDING_DEMOTE),           "d" },          \
  50         {(1UL << GLF_DEMOTE_IN_PROGRESS),       "p" },          \
  51         {(1UL << GLF_DIRTY),                    "y" },          \
  52         {(1UL << GLF_LFLUSH),                   "f" },          \
  53         {(1UL << GLF_INVALIDATE_IN_PROGRESS),   "i" },          \
  54         {(1UL << GLF_REPLY_PENDING),            "r" },          \
  55         {(1UL << GLF_INITIAL),                  "I" },          \
  56         {(1UL << GLF_FROZEN),                   "F" },          \
  57         {(1UL << GLF_QUEUED),                   "q" },          \
  58         {(1UL << GLF_LRU),                      "L" },          \
  59         {(1UL << GLF_OBJECT),                   "o" },          \
  60         {(1UL << GLF_BLOCKING),                 "b" })
  61
  62 #ifndef NUMPTY
  63 #define NUMPTY
  64 static inline u8 glock_trace_state(unsigned int state)
  65 {
  66         switch(state) {
  67         case LM_ST_SHARED:
  68                 return DLM_LOCK_PR;
  69         case LM_ST_DEFERRED:
  70                 return DLM_LOCK_CW;
  71         case LM_ST_EXCLUSIVE:
  72                 return DLM_LOCK_EX;
  73         }
  74         return DLM_LOCK_NL;
  75 }
  76 #endif
  77
  78 /* Section 1 - Locking
  79  *
  80  * Objectives:
  81  * Latency: Remote demote request to state change
  82  * Latency: Local lock request to state change
  83  * Latency: State change to lock grant
  84  * Correctness: Ordering of local lock state vs. I/O requests
  85  * Correctness: Responses to remote demote requests
  86  */
  87
  88 /* General glock state change (DLM lock request completes) */
  89 TRACE_EVENT(gfs2_glock_state_change,
  90
  91         TP_PROTO(const struct gfs2_glock *gl, unsigned int new_state),
  92
  93         TP_ARGS(gl, new_state),
  94
  95         TP_STRUCT__entry(
  96                 __field(        dev_t,  dev                     )
  97                 __field(        u64,    glnum                   )
  98                 __field(        u32,    gltype                  )
  99                 __field(        u8,     cur_state               )
 100                 __field(        u8,     new_state               )
 101                 __field(        u8,     dmt_state               )
 102                 __field(        u8,     tgt_state               )
 103                 __field(        unsigned long,  flags           )
 104         ),
 105
 106         TP_fast_assign(
 107                 __entry->dev            = gl->gl_sbd->sd_vfs->s_dev;
 108                 __entry->glnum          = gl->gl_name.ln_number;
 109                 __entry->gltype         = gl->gl_name.ln_type;
 110                 __entry->cur_state      = glock_trace_state(gl->gl_state);
 111                 __entry->new_state      = glock_trace_state(new_state);
 112                 __entry->tgt_state      = glock_trace_state(gl->gl_target);
 113                 __entry->dmt_state      = glock_trace_state(gl->gl_demote_state);
 114                 __entry->flags          = gl->gl_flags | (gl->gl_object ? (1UL<<GLF_OBJECT) : 0);
 115         ),
 116
 117         TP_printk("%u,%u glock %d:%lld state %s to %s tgt:%s dmt:%s flags:%s",
 118                   MAJOR(__entry->dev), MINOR(__entry->dev), __entry->gltype,
 119                  (unsigned long long)__entry->glnum,
 120                   glock_trace_name(__entry->cur_state),
 121                   glock_trace_name(__entry->new_state),
 122                   glock_trace_name(__entry->tgt_state),
 123                   glock_trace_name(__entry->dmt_state),
 124                   show_glock_flags(__entry->flags))
 125 );
 126
 127 /* State change -> unlocked, glock is being deallocated */
 128 TRACE_EVENT(gfs2_glock_put,
 129
 130         TP_PROTO(const struct gfs2_glock *gl),
 131
 132         TP_ARGS(gl),
 133
 134         TP_STRUCT__entry(
 135                 __field(        dev_t,  dev                     )
 136                 __field(        u64,    glnum                   )
 137                 __field(        u32,    gltype                  )
 138                 __field(        u8,     cur_state               )
 139                 __field(        unsigned long,  flags           )
 140         ),
 141
 142         TP_fast_assign(
 143                 __entry->dev            = gl->gl_sbd->sd_vfs->s_dev;
 144                 __entry->gltype         = gl->gl_name.ln_type;
 145                 __entry->glnum          = gl->gl_name.ln_number;
 146                 __entry->cur_state      = glock_trace_state(gl->gl_state);
 147                 __entry->flags          = gl->gl_flags  | (gl->gl_object ? (1UL<<GLF_OBJECT) : 0);
 148         ),
 149
 150         TP_printk("%u,%u glock %d:%lld state %s => %s flags:%s",
 151                   MAJOR(__entry->dev), MINOR(__entry->dev),
 152                   __entry->gltype, (unsigned long long)__entry->glnum,
 153                   glock_trace_name(__entry->cur_state),
 154                   glock_trace_name(DLM_LOCK_IV),
 155                   show_glock_flags(__entry->flags))
 156
 157 );
 158
 159 /* Callback (local or remote) requesting lock demotion */
 160 TRACE_EVENT(gfs2_demote_rq,
 161
 162         TP_PROTO(const struct gfs2_glock *gl),
 163
 164         TP_ARGS(gl),
 165
 166         TP_STRUCT__entry(
 167                 __field(        dev_t,  dev                     )
 168                 __field(        u64,    glnum                   )
 169                 __field(        u32,    gltype                  )
 170                 __field(        u8,     cur_state               )
 171                 __field(        u8,     dmt_state               )
 172                 __field(        unsigned long,  flags           )
 173         ),
 174
 175         TP_fast_assign(
 176                 __entry->dev            = gl->gl_sbd->sd_vfs->s_dev;
 177                 __entry->gltype         = gl->gl_name.ln_type;
 178                 __entry->glnum          = gl->gl_name.ln_number;
 179                 __entry->cur_state      = glock_trace_state(gl->gl_state);
 180                 __entry->dmt_state      = glock_trace_state(gl->gl_demote_state);
 181                 __entry->flags          = gl->gl_flags  | (gl->gl_object ? (1UL<<GLF_OBJECT) : 0);
 182         ),
 183
 184         TP_printk("%u,%u glock %d:%lld demote %s to %s flags:%s",
 185                   MAJOR(__entry->dev), MINOR(__entry->dev), __entry->gltype,
 186                   (unsigned long long)__entry->glnum,
 187                   glock_trace_name(__entry->cur_state),
 188                   glock_trace_name(__entry->dmt_state),
 189                   show_glock_flags(__entry->flags))
 190
 191 );
 192
 193 /* Promotion/grant of a glock */
 194 TRACE_EVENT(gfs2_promote,
 195
 196         TP_PROTO(const struct gfs2_holder *gh, int first),
 197
 198         TP_ARGS(gh, first),
 199
 200         TP_STRUCT__entry(
 201                 __field(        dev_t,  dev                     )
 202                 __field(        u64,    glnum                   )
 203                 __field(        u32,    gltype                  )
 204                 __field(        int,    first                   )
 205                 __field(        u8,     state                   )
 206         ),
 207
 208         TP_fast_assign(
 209                 __entry->dev    = gh->gh_gl->gl_sbd->sd_vfs->s_dev;
 210                 __entry->glnum  = gh->gh_gl->gl_name.ln_number;
 211                 __entry->gltype = gh->gh_gl->gl_name.ln_type;
 212                 __entry->first  = first;
 213                 __entry->state  = glock_trace_state(gh->gh_state);
 214         ),
 215
 216         TP_printk("%u,%u glock %u:%llu promote %s %s",
 217                   MAJOR(__entry->dev), MINOR(__entry->dev), __entry->gltype,
 218                   (unsigned long long)__entry->glnum,
 219                   __entry->first ? "first": "other",
 220                   glock_trace_name(__entry->state))
 221 );
 222
 223 /* Queue/dequeue a lock request */
 224 TRACE_EVENT(gfs2_glock_queue,
 225
 226         TP_PROTO(const struct gfs2_holder *gh, int queue),
 227
 228         TP_ARGS(gh, queue),
 229
 230         TP_STRUCT__entry(
 231                 __field(        dev_t,  dev                     )
 232                 __field(        u64,    glnum                   )
 233                 __field(        u32,    gltype                  )
 234                 __field(        int,    queue                   )
 235                 __field(        u8,     state                   )
 236         ),
 237
 238         TP_fast_assign(
 239                 __entry->dev    = gh->gh_gl->gl_sbd->sd_vfs->s_dev;
 240                 __entry->glnum  = gh->gh_gl->gl_name.ln_number;
 241                 __entry->gltype = gh->gh_gl->gl_name.ln_type;
 242                 __entry->queue  = queue;
 243                 __entry->state  = glock_trace_state(gh->gh_state);
 244         ),
 245
 246         TP_printk("%u,%u glock %u:%llu %squeue %s",
 247                   MAJOR(__entry->dev), MINOR(__entry->dev), __entry->gltype,
 248                   (unsigned long long)__entry->glnum,
 249                   __entry->queue ? "" : "de",
 250                   glock_trace_name(__entry->state))
 251 );
 252
 253 /* DLM sends a reply to GFS2 */
 254 TRACE_EVENT(gfs2_glock_lock_time,
 255
 256         TP_PROTO(const struct gfs2_glock *gl, s64 tdiff),
 257
 258         TP_ARGS(gl, tdiff),
 259
 260         TP_STRUCT__entry(
 261                 __field(        dev_t,  dev             )
 262                 __field(        u64,    glnum           )
 263                 __field(        u32,    gltype          )
 264                 __field(        int,    status          )
 265                 __field(        char,   flags           )
 266                 __field(        s64,    tdiff           )
 267                 __field(        s64,    srtt            )
 268                 __field(        s64,    srttvar         )
 269                 __field(        s64,    srttb           )
 270                 __field(        s64,    srttvarb        )
 271                 __field(        s64,    sirt            )
 272                 __field(        s64,    sirtvar         )
 273                 __field(        s64,    dcount          )
 274                 __field(        s64,    qcount          )
 275         ),
 276
 277         TP_fast_assign(
 278                 __entry->dev            = gl->gl_sbd->sd_vfs->s_dev;
 279                 __entry->glnum          = gl->gl_name.ln_number;
 280                 __entry->gltype         = gl->gl_name.ln_type;
 281                 __entry->status         = gl->gl_lksb.sb_status;
 282                 __entry->flags          = gl->gl_lksb.sb_flags;
 283                 __entry->tdiff          = tdiff;
 284                 __entry->srtt           = gl->gl_stats.stats[GFS2_LKS_SRTT];
 285                 __entry->srttvar        = gl->gl_stats.stats[GFS2_LKS_SRTTVAR];
 286                 __entry->srttb          = gl->gl_stats.stats[GFS2_LKS_SRTTB];
 287                 __entry->srttvarb       = gl->gl_stats.stats[GFS2_LKS_SRTTVARB];
 288                 __entry->sirt           = gl->gl_stats.stats[GFS2_LKS_SIRT];
 289                 __entry->sirtvar        = gl->gl_stats.stats[GFS2_LKS_SIRTVAR];
 290                 __entry->dcount         = gl->gl_stats.stats[GFS2_LKS_DCOUNT];
 291                 __entry->qcount         = gl->gl_stats.stats[GFS2_LKS_QCOUNT];
 292         ),
 293
 294         TP_printk("%u,%u glock %d:%lld status:%d flags:%02x tdiff:%lld srtt:%lld/%lld srttb:%lld/%lld sirt:%lld/%lld dcnt:%lld qcnt:%lld",
 295                   MAJOR(__entry->dev), MINOR(__entry->dev), __entry->gltype,
 296                   (unsigned long long)__entry->glnum,
 297                   __entry->status, __entry->flags,
 298                   (long long)__entry->tdiff,
 299                   (long long)__entry->srtt,
 300                   (long long)__entry->srttvar,
 301                   (long long)__entry->srttb,
 302                   (long long)__entry->srttvarb,
 303                   (long long)__entry->sirt,
 304                   (long long)__entry->sirtvar,
 305                   (long long)__entry->dcount,
 306                   (long long)__entry->qcount)
 307 );
 308
 309 /* Section 2 - Log/journal
 310  *
 311  * Objectives:
 312  * Latency: Log flush time
 313  * Correctness: pin/unpin vs. disk I/O ordering
 314  * Performance: Log usage stats
 315  */
 316
 317 /* Pin/unpin a block in the log */
 318 TRACE_EVENT(gfs2_pin,
 319
 320         TP_PROTO(const struct gfs2_bufdata *bd, int pin),
 321
 322         TP_ARGS(bd, pin),
 323
 324         TP_STRUCT__entry(
 325                 __field(        dev_t,  dev                     )
 326                 __field(        int,    pin                     )
 327                 __field(        u32,    len                     )
 328                 __field(        sector_t,       block           )
 329                 __field(        u64,    ino                     )
 330         ),
 331
 332         TP_fast_assign(
 333                 __entry->dev            = bd->bd_gl->gl_sbd->sd_vfs->s_dev;
 334                 __entry->pin            = pin;
 335                 __entry->len            = bd->bd_bh->b_size;
 336                 __entry->block          = bd->bd_bh->b_blocknr;
 337                 __entry->ino            = bd->bd_gl->gl_name.ln_number;
 338         ),
 339
 340         TP_printk("%u,%u log %s %llu/%lu inode %llu",
 341                   MAJOR(__entry->dev), MINOR(__entry->dev),
 342                   __entry->pin ? "pin" : "unpin",
 343                   (unsigned long long)__entry->block,
 344                   (unsigned long)__entry->len,
 345                   (unsigned long long)__entry->ino)
 346 );
 347
 348 /* Flushing the log */
 349 TRACE_EVENT(gfs2_log_flush,
 350
 351         TP_PROTO(const struct gfs2_sbd *sdp, int start),
 352
 353         TP_ARGS(sdp, start),
 354
 355         TP_STRUCT__entry(
 356                 __field(        dev_t,  dev                     )
 357                 __field(        int,    start                   )
 358                 __field(        u64,    log_seq                 )
 359         ),
 360
 361         TP_fast_assign(
 362                 __entry->dev            = sdp->sd_vfs->s_dev;
 363                 __entry->start          = start;
 364                 __entry->log_seq        = sdp->sd_log_sequence;
 365         ),
 366
 367         TP_printk("%u,%u log flush %s %llu",
 368                   MAJOR(__entry->dev), MINOR(__entry->dev),
 369                   __entry->start ? "start" : "end",
 370                   (unsigned long long)__entry->log_seq)
 371 );
 372
 373 /* Reserving/releasing blocks in the log */
 374 TRACE_EVENT(gfs2_log_blocks,
 375
 376         TP_PROTO(const struct gfs2_sbd *sdp, int blocks),
 377
 378         TP_ARGS(sdp, blocks),
 379
 380         TP_STRUCT__entry(
 381                 __field(        dev_t,  dev                     )
 382                 __field(        int,    blocks                  )
 383         ),
 384
 385         TP_fast_assign(
 386                 __entry->dev            = sdp->sd_vfs->s_dev;
 387                 __entry->blocks         = blocks;
 388         ),
 389
 390         TP_printk("%u,%u log reserve %d", MAJOR(__entry->dev),
 391                   MINOR(__entry->dev), __entry->blocks)
 392 );
 393
 394 /* Writing back the AIL */
 395 TRACE_EVENT(gfs2_ail_flush,
 396
 397         TP_PROTO(const struct gfs2_sbd *sdp, const struct writeback_control *wbc, int start),
 398
 399         TP_ARGS(sdp, wbc, start),
 400
 401         TP_STRUCT__entry(
 402                 __field(        dev_t,  dev                     )
 403                 __field(        int, start                      )
 404                 __field(        int, sync_mode                  )
 405                 __field(        long, nr_to_write               )
 406         ),
 407
 408         TP_fast_assign(
 409                 __entry->dev            = sdp->sd_vfs->s_dev;
 410                 __entry->start          = start;
 411                 __entry->sync_mode      = wbc->sync_mode;
 412                 __entry->nr_to_write    = wbc->nr_to_write;
 413         ),
 414
 415         TP_printk("%u,%u ail flush %s %s %ld", MAJOR(__entry->dev),
 416                   MINOR(__entry->dev), __entry->start ? "start" : "end",
 417                   __entry->sync_mode == WB_SYNC_ALL ? "all" : "none",
 418                   __entry->nr_to_write)
 419 );
 420
 421 /* Section 3 - bmap
 422  *
 423  * Objectives:
 424  * Latency: Bmap request time
 425  * Performance: Block allocator tracing
 426  * Correctness: Test of disard generation vs. blocks allocated
 427  */
 428
 429 /* Map an extent of blocks, possibly a new allocation */
 430 TRACE_EVENT(gfs2_bmap,
 431
 432         TP_PROTO(const struct gfs2_inode *ip, const struct buffer_head *bh,
 433                 sector_t lblock, int create, int errno),
 434
 435         TP_ARGS(ip, bh, lblock, create, errno),
 436
 437         TP_STRUCT__entry(
 438                 __field(        dev_t,  dev                     )
 439                 __field(        sector_t, lblock                )
 440                 __field(        sector_t, pblock                )
 441                 __field(        u64,    inum                    )
 442                 __field(        unsigned long, state            )
 443                 __field(        u32,    len                     )
 444                 __field(        int,    create                  )
 445                 __field(        int,    errno                   )
 446         ),
 447
 448         TP_fast_assign(
 449                 __entry->dev            = ip->i_gl->gl_sbd->sd_vfs->s_dev;
 450                 __entry->lblock         = lblock;
 451                 __entry->pblock         = buffer_mapped(bh) ?  bh->b_blocknr : 0;
 452                 __entry->inum           = ip->i_no_addr;
 453                 __entry->state          = bh->b_state;
 454                 __entry->len            = bh->b_size;
 455                 __entry->create         = create;
 456                 __entry->errno          = errno;
 457         ),
 458
 459         TP_printk("%u,%u bmap %llu map %llu/%lu to %llu flags:%08lx %s %d",
 460                   MAJOR(__entry->dev), MINOR(__entry->dev),
 461                   (unsigned long long)__entry->inum,
 462                   (unsigned long long)__entry->lblock,
 463                   (unsigned long)__entry->len,
 464                   (unsigned long long)__entry->pblock,
 465                   __entry->state, __entry->create ? "create " : "nocreate",
 466                   __entry->errno)
 467 );
 468
 469 /* Keep track of blocks as they are allocated/freed */
 470 TRACE_EVENT(gfs2_block_alloc,
 471
 472         TP_PROTO(const struct gfs2_inode *ip, struct gfs2_rgrpd *rgd,
 473                  u64 block, unsigned len, u8 block_state),
 474
 475         TP_ARGS(ip, rgd, block, len, block_state),
 476
 477         TP_STRUCT__entry(
 478                 __field(        dev_t,  dev                     )
 479                 __field(        u64,    start                   )
 480                 __field(        u64,    inum                    )
 481                 __field(        u32,    len                     )
 482                 __field(        u8,     block_state             )
 483                 __field(        u64,    rd_addr                 )
 484                 __field(        u32,    rd_free_clone           )
 485                 __field(        u32,    rd_reserved             )
 486         ),
 487
 488         TP_fast_assign(
 489                 __entry->dev            = rgd->rd_gl->gl_sbd->sd_vfs->s_dev;
 490                 __entry->start          = block;
 491                 __entry->inum           = ip->i_no_addr;
 492                 __entry->len            = len;
 493                 __entry->block_state    = block_state;
 494                 __entry->rd_addr        = rgd->rd_addr;
 495                 __entry->rd_free_clone  = rgd->rd_free_clone;
 496                 __entry->rd_reserved    = rgd->rd_reserved;
 497         ),
 498
 499         TP_printk("%u,%u bmap %llu alloc %llu/%lu %s rg:%llu rf:%u rr:%lu",
 500                   MAJOR(__entry->dev), MINOR(__entry->dev),
 501                   (unsigned long long)__entry->inum,
 502                   (unsigned long long)__entry->start,
 503                   (unsigned long)__entry->len,
 504                   block_state_name(__entry->block_state),
 505                   (unsigned long long)__entry->rd_addr,
 506                   __entry->rd_free_clone, (unsigned long)__entry->rd_reserved)
 507 );
 508
 509 /* Keep track of multi-block reservations as they are allocated/freed */
 510 TRACE_EVENT(gfs2_rs,
 511
 512         TP_PROTO(const struct gfs2_blkreserv *rs, u8 func),
 513
 514         TP_ARGS(rs, func),
 515
 516         TP_STRUCT__entry(
 517                 __field(        dev_t,  dev                     )
 518                 __field(        u64,    rd_addr                 )
 519                 __field(        u32,    rd_free_clone           )
 520                 __field(        u32,    rd_reserved             )
 521                 __field(        u64,    inum                    )
 522                 __field(        u64,    start                   )
 523                 __field(        u32,    free                    )
 524                 __field(        u8,     func                    )
 525         ),
 526
 527         TP_fast_assign(
 528                 __entry->dev            = rs->rs_rbm.rgd->rd_sbd->sd_vfs->s_dev;
 529                 __entry->rd_addr        = rs->rs_rbm.rgd->rd_addr;
 530                 __entry->rd_free_clone  = rs->rs_rbm.rgd->rd_free_clone;
 531                 __entry->rd_reserved    = rs->rs_rbm.rgd->rd_reserved;
 532                 __entry->inum           = rs->rs_inum;
 533                 __entry->start          = gfs2_rbm_to_block(&rs->rs_rbm);
 534                 __entry->free           = rs->rs_free;
 535                 __entry->func           = func;
 536         ),
 537
 538         TP_printk("%u,%u bmap %llu resrv %llu rg:%llu rf:%lu rr:%lu %s f:%lu",
 539                   MAJOR(__entry->dev), MINOR(__entry->dev),
 540                   (unsigned long long)__entry->inum,
 541                   (unsigned long long)__entry->start,
 542                   (unsigned long long)__entry->rd_addr,
 543                   (unsigned long)__entry->rd_free_clone,
 544                   (unsigned long)__entry->rd_reserved,
 545                   rs_func_name(__entry->func), (unsigned long)__entry->free)
 546 );
 547
 548 #endif /* _TRACE_GFS2_H */
 549
 550 /* This part must be outside protection */
 551 #undef TRACE_INCLUDE_PATH
 552 #define TRACE_INCLUDE_PATH .
 553 #define TRACE_INCLUDE_FILE trace_gfs2
 554 #include <trace/define_trace.h>
 555