drivers/gpu/drm/i915/intel_guc_log.c

   1 /*
   2  * Copyright © 2014-2017 Intel Corporation
   3  *
   4  * Permission is hereby granted, free of charge, to any person obtaining a
   5  * copy of this software and associated documentation files (the "Software"),
   6  * to deal in the Software without restriction, including without limitation
   7  * the rights to use, copy, modify, merge, publish, distribute, sublicense,
   8  * and/or sell copies of the Software, and to permit persons to whom the
   9  * Software is furnished to do so, subject to the following conditions:
  10  *
  11  * The above copyright notice and this permission notice (including the next
  12  * paragraph) shall be included in all copies or substantial portions of the
  13  * Software.
  14  *
  15  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
  16  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
  17  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
  18  * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
  19  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
  20  * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
  21  * IN THE SOFTWARE.
  22  *
  23  */
  24
  25 #include <linux/debugfs.h>
  26
  27 #include "intel_guc_log.h"
  28 #include "i915_drv.h"
  29
  30 static void guc_log_capture_logs(struct intel_guc_log *log);
  31
  32 /**
  33  * DOC: GuC firmware log
  34  *
  35  * Firmware log is enabled by setting i915.guc_log_level to the positive level.
  36  * Log data is printed out via reading debugfs i915_guc_log_dump. Reading from
  37  * i915_guc_load_status will print out firmware loading status and scratch
  38  * registers value.
  39  */
  40
  41 static int guc_action_flush_log_complete(struct intel_guc *guc)
  42 {
  43         u32 action[] = {
  44                 INTEL_GUC_ACTION_LOG_BUFFER_FILE_FLUSH_COMPLETE
  45         };
  46
  47         return intel_guc_send(guc, action, ARRAY_SIZE(action));
  48 }
  49
  50 static int guc_action_flush_log(struct intel_guc *guc)
  51 {
  52         u32 action[] = {
  53                 INTEL_GUC_ACTION_FORCE_LOG_BUFFER_FLUSH,
  54                 0
  55         };
  56
  57         return intel_guc_send(guc, action, ARRAY_SIZE(action));
  58 }
  59
  60 static int guc_action_control_log(struct intel_guc *guc, bool enable,
  61                                   bool default_logging, u32 verbosity)
  62 {
  63         u32 action[] = {
  64                 INTEL_GUC_ACTION_UK_LOG_ENABLE_LOGGING,
  65                 (enable ? GUC_LOG_CONTROL_LOGGING_ENABLED : 0) |
  66                 (verbosity << GUC_LOG_CONTROL_VERBOSITY_SHIFT) |
  67                 (default_logging ? GUC_LOG_CONTROL_DEFAULT_LOGGING : 0)
  68         };
  69
  70         GEM_BUG_ON(verbosity > GUC_LOG_VERBOSITY_MAX);
  71
  72         return intel_guc_send(guc, action, ARRAY_SIZE(action));
  73 }
  74
  75 static inline struct intel_guc *log_to_guc(struct intel_guc_log *log)
  76 {
  77         return container_of(log, struct intel_guc, log);
  78 }
  79
  80 static void guc_log_enable_flush_events(struct intel_guc_log *log)
  81 {
  82         intel_guc_enable_msg(log_to_guc(log),
  83                              INTEL_GUC_RECV_MSG_FLUSH_LOG_BUFFER |
  84                              INTEL_GUC_RECV_MSG_CRASH_DUMP_POSTED);
  85 }
  86
  87 static void guc_log_disable_flush_events(struct intel_guc_log *log)
  88 {
  89         intel_guc_disable_msg(log_to_guc(log),
  90                               INTEL_GUC_RECV_MSG_FLUSH_LOG_BUFFER |
  91                               INTEL_GUC_RECV_MSG_CRASH_DUMP_POSTED);
  92 }
  93
  94 /*
  95  * Sub buffer switch callback. Called whenever relay has to switch to a new
  96  * sub buffer, relay stays on the same sub buffer if 0 is returned.
  97  */
  98 static int subbuf_start_callback(struct rchan_buf *buf,
  99                                  void *subbuf,
 100                                  void *prev_subbuf,
 101                                  size_t prev_padding)
 102 {
 103         /*
 104          * Use no-overwrite mode by default, where relay will stop accepting
 105          * new data if there are no empty sub buffers left.
 106          * There is no strict synchronization enforced by relay between Consumer
 107          * and Producer. In overwrite mode, there is a possibility of getting
 108          * inconsistent/garbled data, the producer could be writing on to the
 109          * same sub buffer from which Consumer is reading. This can't be avoided
 110          * unless Consumer is fast enough and can always run in tandem with
 111          * Producer.
 112          */
 113         if (relay_buf_full(buf))
 114                 return 0;
 115
 116         return 1;
 117 }
 118
 119 /*
 120  * file_create() callback. Creates relay file in debugfs.
 121  */
 122 static struct dentry *create_buf_file_callback(const char *filename,
 123                                                struct dentry *parent,
 124                                                umode_t mode,
 125                                                struct rchan_buf *buf,
 126                                                int *is_global)
 127 {
 128         struct dentry *buf_file;
 129
 130         /*
 131          * This to enable the use of a single buffer for the relay channel and
 132          * correspondingly have a single file exposed to User, through which
 133          * it can collect the logs in order without any post-processing.
 134          * Need to set 'is_global' even if parent is NULL for early logging.
 135          */
 136         *is_global = 1;
 137
 138         if (!parent)
 139                 return NULL;
 140
 141         buf_file = debugfs_create_file(filename, mode,
 142                                        parent, buf, &relay_file_operations);
 143         return buf_file;
 144 }
 145
 146 /*
 147  * file_remove() default callback. Removes relay file in debugfs.
 148  */
 149 static int remove_buf_file_callback(struct dentry *dentry)
 150 {
 151         debugfs_remove(dentry);
 152         return 0;
 153 }
 154
 155 /* relay channel callbacks */
 156 static struct rchan_callbacks relay_callbacks = {
 157         .subbuf_start = subbuf_start_callback,
 158         .create_buf_file = create_buf_file_callback,
 159         .remove_buf_file = remove_buf_file_callback,
 160 };
 161
 162 static void guc_move_to_next_buf(struct intel_guc_log *log)
 163 {
 164         /*
 165          * Make sure the updates made in the sub buffer are visible when
 166          * Consumer sees the following update to offset inside the sub buffer.
 167          */
 168         smp_wmb();
 169
 170         /* All data has been written, so now move the offset of sub buffer. */
 171         relay_reserve(log->relay.channel, log->vma->obj->base.size);
 172
 173         /* Switch to the next sub buffer */
 174         relay_flush(log->relay.channel);
 175 }
 176
 177 static void *guc_get_write_buffer(struct intel_guc_log *log)
 178 {
 179         /*
 180          * Just get the base address of a new sub buffer and copy data into it
 181          * ourselves. NULL will be returned in no-overwrite mode, if all sub
 182          * buffers are full. Could have used the relay_write() to indirectly
 183          * copy the data, but that would have been bit convoluted, as we need to
 184          * write to only certain locations inside a sub buffer which cannot be
 185          * done without using relay_reserve() along with relay_write(). So its
 186          * better to use relay_reserve() alone.
 187          */
 188         return relay_reserve(log->relay.channel, 0);
 189 }
 190
 191 static bool guc_check_log_buf_overflow(struct intel_guc_log *log,
 192                                        enum guc_log_buffer_type type,
 193                                        unsigned int full_cnt)
 194 {
 195         unsigned int prev_full_cnt = log->stats[type].sampled_overflow;
 196         bool overflow = false;
 197
 198         if (full_cnt != prev_full_cnt) {
 199                 overflow = true;
 200
 201                 log->stats[type].overflow = full_cnt;
 202                 log->stats[type].sampled_overflow += full_cnt - prev_full_cnt;
 203
 204                 if (full_cnt < prev_full_cnt) {
 205                         /* buffer_full_cnt is a 4 bit counter */
 206                         log->stats[type].sampled_overflow += 16;
 207                 }
 208                 DRM_ERROR_RATELIMITED("GuC log buffer overflow\n");
 209         }
 210
 211         return overflow;
 212 }
 213
 214 static unsigned int guc_get_log_buffer_size(enum guc_log_buffer_type type)
 215 {
 216         switch (type) {
 217         case GUC_ISR_LOG_BUFFER:
 218                 return ISR_BUFFER_SIZE;
 219         case GUC_DPC_LOG_BUFFER:
 220                 return DPC_BUFFER_SIZE;
 221         case GUC_CRASH_DUMP_LOG_BUFFER:
 222                 return CRASH_BUFFER_SIZE;
 223         default:
 224                 MISSING_CASE(type);
 225         }
 226
 227         return 0;
 228 }
 229
 230 static void guc_read_update_log_buffer(struct intel_guc_log *log)
 231 {
 232         unsigned int buffer_size, read_offset, write_offset, bytes_to_copy, full_cnt;
 233         struct guc_log_buffer_state *log_buf_state, *log_buf_snapshot_state;
 234         struct guc_log_buffer_state log_buf_state_local;
 235         enum guc_log_buffer_type type;
 236         void *src_data, *dst_data;
 237         bool new_overflow;
 238
 239         mutex_lock(&log->relay.lock);
 240
 241         if (WARN_ON(!intel_guc_log_relay_enabled(log)))
 242                 goto out_unlock;
 243
 244         /* Get the pointer to shared GuC log buffer */
 245         log_buf_state = src_data = log->relay.buf_addr;
 246
 247         /* Get the pointer to local buffer to store the logs */
 248         log_buf_snapshot_state = dst_data = guc_get_write_buffer(log);
 249
 250         if (unlikely(!log_buf_snapshot_state)) {
 251                 /*
 252                  * Used rate limited to avoid deluge of messages, logs might be
 253                  * getting consumed by User at a slow rate.
 254                  */
 255                 DRM_ERROR_RATELIMITED("no sub-buffer to capture logs\n");
 256                 log->relay.full_count++;
 257
 258                 goto out_unlock;
 259         }
 260
 261         /* Actual logs are present from the 2nd page */
 262         src_data += PAGE_SIZE;
 263         dst_data += PAGE_SIZE;
 264
 265         for (type = GUC_ISR_LOG_BUFFER; type < GUC_MAX_LOG_BUFFER; type++) {
 266                 /*
 267                  * Make a copy of the state structure, inside GuC log buffer
 268                  * (which is uncached mapped), on the stack to avoid reading
 269                  * from it multiple times.
 270                  */
 271                 memcpy(&log_buf_state_local, log_buf_state,
 272                        sizeof(struct guc_log_buffer_state));
 273                 buffer_size = guc_get_log_buffer_size(type);
 274                 read_offset = log_buf_state_local.read_ptr;
 275                 write_offset = log_buf_state_local.sampled_write_ptr;
 276                 full_cnt = log_buf_state_local.buffer_full_cnt;
 277
 278                 /* Bookkeeping stuff */
 279                 log->stats[type].flush += log_buf_state_local.flush_to_file;
 280                 new_overflow = guc_check_log_buf_overflow(log, type, full_cnt);
 281
 282                 /* Update the state of shared log buffer */
 283                 log_buf_state->read_ptr = write_offset;
 284                 log_buf_state->flush_to_file = 0;
 285                 log_buf_state++;
 286
 287                 /* First copy the state structure in snapshot buffer */
 288                 memcpy(log_buf_snapshot_state, &log_buf_state_local,
 289                        sizeof(struct guc_log_buffer_state));
 290
 291                 /*
 292                  * The write pointer could have been updated by GuC firmware,
 293                  * after sending the flush interrupt to Host, for consistency
 294                  * set write pointer value to same value of sampled_write_ptr
 295                  * in the snapshot buffer.
 296                  */
 297                 log_buf_snapshot_state->write_ptr = write_offset;
 298                 log_buf_snapshot_state++;
 299
 300                 /* Now copy the actual logs. */
 301                 if (unlikely(new_overflow)) {
 302                         /* copy the whole buffer in case of overflow */
 303                         read_offset = 0;
 304                         write_offset = buffer_size;
 305                 } else if (unlikely((read_offset > buffer_size) ||
 306                                     (write_offset > buffer_size))) {
 307                         DRM_ERROR("invalid log buffer state\n");
 308                         /* copy whole buffer as offsets are unreliable */
 309                         read_offset = 0;
 310                         write_offset = buffer_size;
 311                 }
 312
 313                 /* Just copy the newly written data */
 314                 if (read_offset > write_offset) {
 315                         i915_memcpy_from_wc(dst_data, src_data, write_offset);
 316                         bytes_to_copy = buffer_size - read_offset;
 317                 } else {
 318                         bytes_to_copy = write_offset - read_offset;
 319                 }
 320                 i915_memcpy_from_wc(dst_data + read_offset,
 321                                     src_data + read_offset, bytes_to_copy);
 322
 323                 src_data += buffer_size;
 324                 dst_data += buffer_size;
 325         }
 326
 327         guc_move_to_next_buf(log);
 328
 329 out_unlock:
 330         mutex_unlock(&log->relay.lock);
 331 }
 332
 333 static void capture_logs_work(struct work_struct *work)
 334 {
 335         struct intel_guc_log *log =
 336                 container_of(work, struct intel_guc_log, relay.flush_work);
 337
 338         guc_log_capture_logs(log);
 339 }
 340
 341 static int guc_log_map(struct intel_guc_log *log)
 342 {
 343         struct intel_guc *guc = log_to_guc(log);
 344         struct drm_i915_private *dev_priv = guc_to_i915(guc);
 345         void *vaddr;
 346         int ret;
 347
 348         lockdep_assert_held(&log->relay.lock);
 349
 350         if (!log->vma)
 351                 return -ENODEV;
 352
 353         mutex_lock(&dev_priv->drm.struct_mutex);
 354         ret = i915_gem_object_set_to_wc_domain(log->vma->obj, true);
 355         mutex_unlock(&dev_priv->drm.struct_mutex);
 356         if (ret)
 357                 return ret;
 358
 359         /*
 360          * Create a WC (Uncached for read) vmalloc mapping of log
 361          * buffer pages, so that we can directly get the data
 362          * (up-to-date) from memory.
 363          */
 364         vaddr = i915_gem_object_pin_map(log->vma->obj, I915_MAP_WC);
 365         if (IS_ERR(vaddr)) {
 366                 DRM_ERROR("Couldn't map log buffer pages %d\n", ret);
 367                 return PTR_ERR(vaddr);
 368         }
 369
 370         log->relay.buf_addr = vaddr;
 371
 372         return 0;
 373 }
 374
 375 static void guc_log_unmap(struct intel_guc_log *log)
 376 {
 377         lockdep_assert_held(&log->relay.lock);
 378
 379         i915_gem_object_unpin_map(log->vma->obj);
 380         log->relay.buf_addr = NULL;
 381 }
 382
 383 void intel_guc_log_init_early(struct intel_guc_log *log)
 384 {
 385         mutex_init(&log->relay.lock);
 386         INIT_WORK(&log->relay.flush_work, capture_logs_work);
 387 }
 388
 389 static int guc_log_relay_create(struct intel_guc_log *log)
 390 {
 391         struct intel_guc *guc = log_to_guc(log);
 392         struct drm_i915_private *dev_priv = guc_to_i915(guc);
 393         struct rchan *guc_log_relay_chan;
 394         size_t n_subbufs, subbuf_size;
 395         int ret;
 396
 397         lockdep_assert_held(&log->relay.lock);
 398
 399          /* Keep the size of sub buffers same as shared log buffer */
 400         subbuf_size = log->vma->size;
 401
 402         /*
 403          * Store up to 8 snapshots, which is large enough to buffer sufficient
 404          * boot time logs and provides enough leeway to User, in terms of
 405          * latency, for consuming the logs from relay. Also doesn't take
 406          * up too much memory.
 407          */
 408         n_subbufs = 8;
 409
 410         guc_log_relay_chan = relay_open("guc_log",
 411                                         dev_priv->drm.primary->debugfs_root,
 412                                         subbuf_size, n_subbufs,
 413                                         &relay_callbacks, dev_priv);
 414         if (!guc_log_relay_chan) {
 415                 DRM_ERROR("Couldn't create relay chan for GuC logging\n");
 416
 417                 ret = -ENOMEM;
 418                 return ret;
 419         }
 420
 421         GEM_BUG_ON(guc_log_relay_chan->subbuf_size < subbuf_size);
 422         log->relay.channel = guc_log_relay_chan;
 423
 424         return 0;
 425 }
 426
 427 static void guc_log_relay_destroy(struct intel_guc_log *log)
 428 {
 429         lockdep_assert_held(&log->relay.lock);
 430
 431         relay_close(log->relay.channel);
 432         log->relay.channel = NULL;
 433 }
 434
 435 static void guc_log_capture_logs(struct intel_guc_log *log)
 436 {
 437         struct intel_guc *guc = log_to_guc(log);
 438         struct drm_i915_private *dev_priv = guc_to_i915(guc);
 439
 440         guc_read_update_log_buffer(log);
 441
 442         /*
 443          * Generally device is expected to be active only at this
 444          * time, so get/put should be really quick.
 445          */
 446         intel_runtime_pm_get(dev_priv);
 447         guc_action_flush_log_complete(guc);
 448         intel_runtime_pm_put(dev_priv);
 449 }
 450
 451 int intel_guc_log_create(struct intel_guc_log *log)
 452 {
 453         struct intel_guc *guc = log_to_guc(log);
 454         struct i915_vma *vma;
 455         u32 guc_log_size;
 456         int ret;
 457
 458         GEM_BUG_ON(log->vma);
 459
 460         /*
 461          *  GuC Log buffer Layout
 462          *
 463          *  +===============================+ 00B
 464          *  |    Crash dump state header    |
 465          *  +-------------------------------+ 32B
 466          *  |       DPC state header        |
 467          *  +-------------------------------+ 64B
 468          *  |       ISR state header        |
 469          *  +-------------------------------+ 96B
 470          *  |                               |
 471          *  +===============================+ PAGE_SIZE (4KB)
 472          *  |        Crash Dump logs        |
 473          *  +===============================+ + CRASH_SIZE
 474          *  |           DPC logs            |
 475          *  +===============================+ + DPC_SIZE
 476          *  |           ISR logs            |
 477          *  +===============================+ + ISR_SIZE
 478          */
 479         guc_log_size = PAGE_SIZE + CRASH_BUFFER_SIZE + DPC_BUFFER_SIZE +
 480                         ISR_BUFFER_SIZE;
 481
 482         vma = intel_guc_allocate_vma(guc, guc_log_size);
 483         if (IS_ERR(vma)) {
 484                 ret = PTR_ERR(vma);
 485                 goto err;
 486         }
 487
 488         log->vma = vma;
 489
 490         log->level = i915_modparams.guc_log_level;
 491
 492         return 0;
 493
 494 err:
 495         DRM_ERROR("Failed to allocate GuC log buffer. %d\n", ret);
 496         return ret;
 497 }
 498
 499 void intel_guc_log_destroy(struct intel_guc_log *log)
 500 {
 501         i915_vma_unpin_and_release(&log->vma, 0);
 502 }
 503
 504 int intel_guc_log_set_level(struct intel_guc_log *log, u32 level)
 505 {
 506         struct intel_guc *guc = log_to_guc(log);
 507         struct drm_i915_private *dev_priv = guc_to_i915(guc);
 508         int ret;
 509
 510         BUILD_BUG_ON(GUC_LOG_VERBOSITY_MIN != 0);
 511         GEM_BUG_ON(!log->vma);
 512
 513         /*
 514          * GuC is recognizing log levels starting from 0 to max, we're using 0
 515          * as indication that logging should be disabled.
 516          */
 517         if (level < GUC_LOG_LEVEL_DISABLED || level > GUC_LOG_LEVEL_MAX)
 518                 return -EINVAL;
 519
 520         mutex_lock(&dev_priv->drm.struct_mutex);
 521
 522         if (log->level == level) {
 523                 ret = 0;
 524                 goto out_unlock;
 525         }
 526
 527         intel_runtime_pm_get(dev_priv);
 528         ret = guc_action_control_log(guc, GUC_LOG_LEVEL_IS_VERBOSE(level),
 529                                      GUC_LOG_LEVEL_IS_ENABLED(level),
 530                                      GUC_LOG_LEVEL_TO_VERBOSITY(level));
 531         intel_runtime_pm_put(dev_priv);
 532         if (ret) {
 533                 DRM_DEBUG_DRIVER("guc_log_control action failed %d\n", ret);
 534                 goto out_unlock;
 535         }
 536
 537         log->level = level;
 538
 539 out_unlock:
 540         mutex_unlock(&dev_priv->drm.struct_mutex);
 541
 542         return ret;
 543 }
 544
 545 bool intel_guc_log_relay_enabled(const struct intel_guc_log *log)
 546 {
 547         return log->relay.buf_addr;
 548 }
 549
 550 int intel_guc_log_relay_open(struct intel_guc_log *log)
 551 {
 552         int ret;
 553
 554         mutex_lock(&log->relay.lock);
 555
 556         if (intel_guc_log_relay_enabled(log)) {
 557                 ret = -EEXIST;
 558                 goto out_unlock;
 559         }
 560
 561         /*
 562          * We require SSE 4.1 for fast reads from the GuC log buffer and
 563          * it should be present on the chipsets supporting GuC based
 564          * submisssions.
 565          */
 566         if (!i915_has_memcpy_from_wc()) {
 567                 ret = -ENXIO;
 568                 goto out_unlock;
 569         }
 570
 571         ret = guc_log_relay_create(log);
 572         if (ret)
 573                 goto out_unlock;
 574
 575         ret = guc_log_map(log);
 576         if (ret)
 577                 goto out_relay;
 578
 579         mutex_unlock(&log->relay.lock);
 580
 581         guc_log_enable_flush_events(log);
 582
 583         /*
 584          * When GuC is logging without us relaying to userspace, we're ignoring
 585          * the flush notification. This means that we need to unconditionally
 586          * flush on relay enabling, since GuC only notifies us once.
 587          */
 588         queue_work(log->relay.flush_wq, &log->relay.flush_work);
 589
 590         return 0;
 591
 592 out_relay:
 593         guc_log_relay_destroy(log);
 594 out_unlock:
 595         mutex_unlock(&log->relay.lock);
 596
 597         return ret;
 598 }
 599
 600 void intel_guc_log_relay_flush(struct intel_guc_log *log)
 601 {
 602         struct intel_guc *guc = log_to_guc(log);
 603         struct drm_i915_private *i915 = guc_to_i915(guc);
 604
 605         /*
 606          * Before initiating the forceful flush, wait for any pending/ongoing
 607          * flush to complete otherwise forceful flush may not actually happen.
 608          */
 609         flush_work(&log->relay.flush_work);
 610
 611         intel_runtime_pm_get(i915);
 612         guc_action_flush_log(guc);
 613         intel_runtime_pm_put(i915);
 614
 615         /* GuC would have updated log buffer by now, so capture it */
 616         guc_log_capture_logs(log);
 617 }
 618
 619 void intel_guc_log_relay_close(struct intel_guc_log *log)
 620 {
 621         guc_log_disable_flush_events(log);
 622         flush_work(&log->relay.flush_work);
 623
 624         mutex_lock(&log->relay.lock);
 625         GEM_BUG_ON(!intel_guc_log_relay_enabled(log));
 626         guc_log_unmap(log);
 627         guc_log_relay_destroy(log);
 628         mutex_unlock(&log->relay.lock);
 629 }
 630
 631 void intel_guc_log_handle_flush_event(struct intel_guc_log *log)
 632 {
 633         queue_work(log->relay.flush_wq, &log->relay.flush_work);
 634 }