如何识别脚本中最耗时的部分

Posted 2023-03-06

【中文标题】如何识别脚本中最耗时的部分

【英文标题】：How to identify the most time-consuming parts of the script

【发布时间】：2020-03-11 14:45:11

【问题描述】：

特别是对于长脚本和许多函数，可能很难确定代码的哪些部分需要最多的时间来处理。

识别这些很重要，因为加速耗时的代码部分，无论是运行一次还是因为代码经常重复，都可以最大程度地减少处理时间。

如何有效地跟踪？

【问题讨论】：

R 需要一个分析包，例如 Visual VM for Java。 visualvm.github.io

签出：adv-r.hadley.nz/perf-measure.html

看到这个答案：***.com/questions/13403990/…

【参考方案1】：

考虑以下三个函数：Start()、End() 和 Timestamps()。

要开始跟踪进程的时间，请在要处理的代码的开头添加Start() 函数。您必须指定一个标签来描述正在对哪些代码进行时间跟踪，并且您必须指定要将时间戳保存到哪个全局变量。

同样，End() 将停止跟踪最后一个被跟踪进程的时间。在这里，您只需提供全局变量作为参数。不必显式应用End()，因为使用Start() 启动一个新的时间跟踪实例会自动执行此操作。但是，如果您明确想要结束时间跟踪，End() 很有用。

最后，Timestamps() 将通过标签汇总所有时间戳，该函数将提供平均值、变异系数、带有该标签的时间戳数量以及带有该标签的时间戳所花费的总时间。这些结果将打印到控制台。

library(dplyr)

Start() 函数：

Start <- function(label, time_stamps)

  # ————————————————————————————————————————————————————————————————————————————
  # See if timestamp exists and create a new global env variable if not
  # ————————————————————————————————————————————————————————————————————————————

  time_stamps_exists <- exists(as.character(substitute(time_stamps)), envir=.GlobalEnv)

  if (!time_stamps_exists)
    assign(
      x = deparse(substitute(time_stamps)), 
      value = data.frame(
        label = character(),
        start = character(),
        end = character(),
        duration = numeric(),
        stringsAsFactors = F
      ), 
      env = .GlobalEnv)
  


  # ————————————————————————————————————————————————————————————————————————————
  # Get the global env variable
  # ————————————————————————————————————————————————————————————————————————————

  df <- get(
    x = deparse(substitute(time_stamps)), 
    envir = .GlobalEnv)


  # ————————————————————————————————————————————————————————————————————————————
  # Add end stamp and duration on last instance if not done yet
  # ————————————————————————————————————————————————————————————————————————————

  if (nrow(df) > 0 && is.na(df$end[nrow(df)]))
    end_stamp <- 
      as.POSIXlt(Sys.time(), "%Y-%m-%d %H:%M:%OS3", tz = "CET") %>% 
      format(., "%Y-%m-%d %H:%M:%OS3")

    df$end[nrow(df)] <- end_stamp

    df$duration[nrow(df)] <- 
      difftime(
        df$end[nrow(df)], 
        df$start[nrow(df)], 
        units=c("secs")) %>%
      as.numeric()
  


  # ————————————————————————————————————————————————————————————————————————————
  # Create new row
  # ————————————————————————————————————————————————————————————————————————————

  df. <- data.frame(
    label = label,
    start = 
      as.POSIXlt(Sys.time(), "%Y-%m-%d %H:%M:%OS3", tz = "CET") %>% 
      format(., "%Y-%m-%d %H:%M:%OS3"),
    end = as.POSIXct("", format="%Y-%m-%d"),
    duration = NaN,
    stringsAsFactors = F
  )

  df <- rbind(df, df.)


  # ————————————————————————————————————————————————————————————————————————————
  # Save to global env variable
  # ————————————————————————————————————————————————————————————————————————————

  assign(
    x = deparse(substitute(time_stamps)), 
    value = df, 
    env = .GlobalEnv)

End() 函数：

End <- function(time_stamps, label = NULL)

  # ————————————————————————————————————————————————————————————————————————————
  # Get the global env variable
  # ————————————————————————————————————————————————————————————————————————————

  df <- get(
    x = deparse(substitute(time_stamps)),
    envir = .GlobalEnv)


  # ————————————————————————————————————————————————————————————————————————————
  # Add end stamp and duration on last instance if not done yet
  # ————————————————————————————————————————————————————————————————————————————

  end_stamp <-
    as.POSIXlt(Sys.time(), "%Y-%m-%d %H:%M:%OS3", tz = "CET") %>%
    format(., "%Y-%m-%d %H:%M:%OS3")

  df$end[nrow(df)] <- end_stamp

  df$duration[nrow(df)] <-
    difftime(
      df$end[nrow(df)],
      df$start[nrow(df)],
      units=c("secs")) %>%
    as.numeric()


  # ————————————————————————————————————————————————————————————————————————————
  # Save to global env variable
  # ————————————————————————————————————————————————————————————————————————————

  assign(
    x = deparse(substitute(time_stamps)),
    value = df,
    env = .GlobalEnv)

  if (!is.null(label))
    printf("Ended %s", label)
  

Timestamps() 函数

Timestamps <- function(time_stamps, end_last = FALSE, head = NULL)

  # ————————————————————————————————————————————————————————————————————————————
  # Get the global env variable
  # ————————————————————————————————————————————————————————————————————————————

  df <- get(
    x = deparse(substitute(time_stamps)), 
    envir = .GlobalEnv)


  # ————————————————————————————————————————————————————————————————————————————
  # End last timestmap if necessary and reload the global env variable
  # ————————————————————————————————————————————————————————————————————————————

  if (nrow(df) > 0 && is.na(df$end[nrow(df)]))
    End(time_stamps, "timestamp to study summary")

    df <- get(
      x = deparse(substitute(time_stamps)), 
      envir = .GlobalEnv)
  


  # ————————————————————————————————————————————————————————————————————————————
  # Create summary to be printed
  # ————————————————————————————————————————————————————————————————————————————

  output <- data.frame(
    label = unique(df$label),
    mean  = c(NaN),
    cv    = c(NaN),
    n     = c(NaN)
  )

  for (row in 1:nrow(output)) 
    label_in_question <- output$label[row]

    durations <- df$duration[df$label == label_in_question]

    output$mean[row] <- mean(durations)
    output$cv[row] <- cv(durations)
    output$n[row] <- sum(df$label == label_in_question)
  

  output$total_time <- output$mean * output$n

  output <- output[order(output$mean, decreasing = TRUE),]

  if (!is.null(head))
    print(head(output, head))
  else
    print(output)
  

示例

for (i in 1:3) 
  Start("Running the 1st for loop", foo)
  Sys.sleep(2)
  End(foo)


Timestamps(foo)

但是，如果在下一个Start() 之前没有调用End()，那么在启动新实例之前，最后一个实例的时间戳将自动停止。上面的代码等价于下面的代码，并产生相同的结果：

for (i in 1:3) 
  Start("Running the 1st for loop", foo)
  Sys.sleep(2)


Timestamps(foo, end_last = TRUE)

最后，运行Timestamps(foo) 会打印以下输出：

   label                     mean   cv          n  total_time
1  Running the 1st for loop  2.004  0.08643715  3  6.012