【问题标题】:What caused my elapsed time much longer than user time?是什么导致我经过的时间比用户时间长得多?
【发布时间】:2012-12-03 17:46:38
【问题描述】:

我正在对一些 R 语句进行基准测试(请参阅详细信息 here),发现我经过的时间比我的用户时间长得多。

   user  system elapsed 
  7.910   7.750  53.916 

有人可以帮助我了解哪些因素(R 或硬件)决定了用户时间和经过时间之间的差异,以及如何改进它?如果有帮助的话:我正在一台配备 4GB RAM 的 Macbook Air 1.7Ghz i5 上运行 data.table 数据操作。

更新:我粗略的理解是,用户时间是我的 CPU 用来处理我的工作的时间。经过时间是从我提交作业到我取回数据的时间。处理 8 秒后,我的电脑还需要做什么?

更新:按照评论中的建议,我在两个 data.table 上运行了几次:Y,有 104 列(抱歉,随着时间的推移,我添加了更多列),X 作为 Y 的子集,只有 3键。以下是更新。请注意,我连续运行了这两个程序,所以内存状态应该是相似的。

 X<- Y[, list(Year, MemberID, Month)]

 system.time(
   {X[ , Month:= -Month]
   setkey(X,Year, MemberID, Month)
   X[,Month:=-Month]}
  )
   user  system elapsed 
  3.490   0.031   3.519 

 system.time(
 {Y[ , Month:= -Month]
  setkey(Y,Year, MemberID, Month)
  Y[,Month:=-Month]}
 )
   user  system elapsed 
  8.444   5.564  36.284 

这是我工作区中仅有的两个对象的大小(添加了逗号)。 :

object.size(X)
83,237,624 bytes

 object.size(Y)
2,449,521,080 bytes

谢谢

【问题讨论】:

  • 参见?proc.time,正如?system.time 所建议的那样。你能澄清一下你对那里写的东西感到困惑的地方吗?
  • 我粗略的理解是,用户时间是我的 CPU 用来处理我的工作的时间。经过时间是从我提交作业到我取回数据的时间。处理 8 秒后,我的电脑还需要做什么?
  • 另外,一个可重现的例子会有很长的路要走。
  • 这不取决于您在计算机上运行的其他进程吗?也许是一个愚蠢的问题,但也许确保你在计时时退出了其他应用程序?
  • 当您看到这种行为时,您的交换使用量是多少?有了 4G 的 RAM 和一个几乎 2.5G 的对象,我预计会有一些争用。您可能只需要更多 RAM。

标签: performance r


【解决方案1】:

用户时间是计算机用于计算的秒数。系统时间是操作系统响应程序请求所花费的时间。经过的时间是这两者的总和,加上你的程序和/或操作系统必须做的任何“等待”。需要注意的是,这些数字是所花费时间的总和。您的程序可能会计算 1 秒,然后在操作系统上等待 1 秒,然后在磁盘上等待 3 秒,并在运行时重复此循环多次。

基于您的程序占用的系统时间与用户时间一样多的事实,这是一个非常 IO 密集型的事情。从磁盘读取很多或写入磁盘很多。 RAM 非常快,通常为几百纳秒。因此,如果一切都适合 RAM,则经过的时间通常比用户时间长一点。但是磁盘可能需要几毫秒的时间来寻找,甚至更长的时间来回复数据。这慢了一百万倍。

我们已确定您的处理器“工作”了 ~8 + ~8 = ~ 16 秒。另一个 ~54 - ~16 = ~38 秒是做什么的?等待硬盘向它发送它要求的数据。

更新1:

马修提出了一些很好的观点,我做出了一些我可能不应该做出的假设。 Adam,如果您愿意发布表中所有行的列表(我们只需要数据类型),我们可以更好地了解正在发生的事情。

我刚刚编写了一个什么都不做的小程序来验证我的假设,即未花费在用户空间和内核空间的时间很可能用于等待 IO。

#include <stdio.h>
int main()
{
    int i;
    for(i = 0; i < 1000000000; i++)
    {
        int j, k, l, m;
        j = 10;
        k = i;
        l = j + k;
        m = j + k - i + l;
    }
    return 0;
}

当我运行生成的程序并对其计时时,我会看到如下内容:

mike@computer:~$ time ./waste_user
real    0m4.670s
user    0m4.660s
sys 0m0.000s
mike@computer:~$ 

正如您通过检查看到的那样,该程序并没有真正的工作,因此它不会要求内核做任何事情,只是将其加载到 RAM 中并开始运行。所以几乎所有的“真实”时间都花在了“用户”时间上。

现在是一个内核重的无操作程序(减少了几次迭代以保持时间合理):

#include <stdio.h>
int main()
{
    FILE * random;
    random = fopen("/dev/urandom", "r");
    int i;
    for(i = 0; i < 10000000; i++)
    {
        fgetc(random);
    }
    return 0;
}

当我运行那个时,我看到的更像是这样的:

mike@computer:~$ time ./waste_sys
real    0m1.138s
user    0m0.090s
sys     0m1.040s
mike@computer:~$ 

再次通过检查很容易看出,程序只是要求内核给它随机字节。 /dev/urandom 是一个非阻塞的熵源。这意味着什么?内核使用伪随机数生成器为我们的小测试程序快速生成“随机”值。这意味着内核必须进行一些计算,但它可以很快返回。所以这个程序主要是等待内核为它计算,我们可以看到几乎所有的时间都花在了 sys 上。

现在我们要做一点改变。我们不会从非阻塞的 /dev/urandom 读取,而是从阻塞的 /dev/random 读取。这意味着什么?它不会做太多的计算,而是等待内核开发人员根据经验确定是随机的事情发生在您的计算机上。 (我们也将做更少的迭代,因为这些东西需要更长的时间)

#include <stdio.h>
int main()
{
    FILE * random;
    random = fopen("/dev/random", "r");
    int i;
    for(i = 0; i < 100; i++)
    {
        fgetc(random);
    }
    return 0;
}

当我运行这个版本的程序并计时时,我看到的是:

mike@computer:~$ time ./waste_io
real    0m41.451s
user    0m0.000s
sys     0m0.000s
mike@computer:~$ 

运行需要 41 秒,但在用户和真实用户上的时间非常少。这是为什么?所有时间都花在内核中,但没有进行主动计算。内核只是在等待事情发生。一旦收集到足够的熵,内核就会重新唤醒并将数据发送回程序。 (请注意,根据发生的情况,在您的计算机上运行可能需要更少或更多的时间)。我认为 user+sys 和 real 之间的时间差异是 IO。

那么这一切意味着什么?这并不能证明我的回答是正确的,因为可能还有其他解释可以解释为什么您会看到自己的行为。但它确实展示了用户计算时间、内核计算时间和我所说的花在 IO 上的时间之间的差异。

这是 /dev/urandom 和 /dev/random 之间区别的来源: http://en.wikipedia.org/wiki//dev/random

更新2:

我想我会尝试解决 Matthew 的建议,即 L2 缓存未命中可能是问题的根源。 Core i7 有一个 64 字节的高速缓存行。我不知道您对缓存了解多少,所以我将提供一些详细信息。当你从内存中请求一个值时,CPU 不会只得到那个值,它会得到它周围的所有 64 个字节。这意味着如果您以非常可预测的模式访问内存——比如数组[0]、数组[1]、数组[2]等——需要一段时间才能获得值 0,然后是 1、2, 3, 4... 快得多。直到你到达下一个缓存行,就是这样。如果这是一个整数数组,0 会很慢,1..15 会很快,16 会很慢,17..31 会很快,等等。

http://software.intel.com/en-us/forums/topic/296674

为了测试这一点,我制作了两个程序。它们都有一个结构数组,其中包含 1024*1024 个元素。在一种情况下,结构中有一个双精度,在另一种情况下,它有 8 个双精度。 double 的长度为 8 个字节,因此在第二个程序中,我们以最糟糕的方式访问内存以获取缓存。第一个将很好地使用缓存。

#include <stdio.h>
#include <stdlib.h>
#define MANY_MEGS 1048576
typedef struct {
    double a;
} PartialLine;
int main()
{
    int i, j;
    PartialLine* many_lines;
    int total_bytes = MANY_MEGS * sizeof(PartialLine);
    printf("Striding through %d total bytes, %d bytes at a time\n", total_bytes, sizeof(PartialLine));
    many_lines = (PartialLine*) malloc(total_bytes);
    PartialLine line;
    double x;
    for(i = 0; i < 300; i++)
    {
        for(j = 0; j < MANY_MEGS; j++)
        {
            line = many_lines[j];
            x = line.a;
        }
    }
    return 0;
}

当我运行这个程序时,我看到了这个输出:

mike@computer:~$ time ./cache_hits
Striding through 8388608 total bytes, 8 bytes at a time
real    0m3.194s
user    0m3.140s
sys     0m0.016s
mike@computer:~$

这是具有大结构的程序,它们每个占用 64 个字节的内存,而不是 8 个。

#include <stdio.h>
#include <stdlib.h>
#define MANY_MEGS 1048576
typedef struct {
    double a, b, c, d, e, f, g, h;
} WholeLine;
int main()
{
    int i, j;
    WholeLine* many_lines;
    int total_bytes = MANY_MEGS * sizeof(WholeLine);
    printf("Striding through %d total bytes, %d bytes at a time\n", total_bytes, sizeof(WholeLine));
    many_lines = (WholeLine*) malloc(total_bytes);
    WholeLine line;
    double x;
    for(i = 0; i < 300; i++)
    {
        for(j = 0; j < MANY_MEGS; j++)
        {
            line = many_lines[j];
            x = line.a;
        }
    }
    return 0;
}

当我运行它时,我看到了这个:

mike@computer:~$ time ./cache_misses
Striding through 67108864 total bytes, 64 bytes at a time
real    0m14.367s
user    0m14.245s
sys     0m0.088s
mike@computer:~$ 

第二个程序——设计用于缓存未命中的程序——运行相同数量的内存访问需要五倍的时间。

另外值得注意的是,在这两种情况下,所有花费的时间都花在了 user 上,而不是 sys 上。这意味着操作系统正在计算您的程序必须等待针对您的程序而不是针对操作系统的数据的时间。鉴于这两个示例,我认为缓存未命中不太可能导致您经过的时间大大长于您的用户时间。

更新3:

我刚刚看到你的更新,真正瘦身的桌子比普通尺寸的桌子快大约 10 倍。这也会向我表明(正如另一位 Matthew 所说)你的 RAM 用完了。

一旦您的程序尝试使用比计算机实际安装更多的内存,它就会开始交换到磁盘。这比您的程序崩溃要好,但它比 RAM 慢得多,并且可能导致严重的减速。

我明天会尝试整理一个显示交换问题的示例。

更新4:

好的,这是一个与上一个非常相似的示例程序。但是现在结构是 4096 字节,而不是 8 字节。该程序总共将使用 2GB 内存而不是 64MB。我还做了一些改动,并确保我随机访问事物而不是逐个元素地访问,这样内核就无法变得聪明并开始预测我的程序需求。缓存由硬件驱动(仅由简单的启发式驱动),但 kswapd(内核交换守护进程)完全有可能比缓存更智能。

#include <stdio.h>
#include <stdlib.h>
typedef struct {
    double numbers[512];
} WholePage;
int main()
{
    int memory_ops = 1024*1024;
    int total_memory = memory_ops / 2;
    int num_chunks = 8;
    int chunk_bytes = total_memory / num_chunks * sizeof(WholePage);
    int i, j, k, l;
    printf("Bouncing through %u MB, %d bytes at a time\n", chunk_bytes/1024*num_chunks/1024, sizeof(WholePage));
    WholePage* many_pages[num_chunks];
    for(i = 0; i < num_chunks; i++)
    {
        many_pages[i] = (WholePage*) malloc(chunk_bytes);
        if(many_pages[i] == 0){ exit(1); }
    }
    WholePage* page_list;
    WholePage* page;
    double x;
    for(i = 0; i < 300*memory_ops; i++)
    {
        j = rand() % num_chunks;
        k = rand() % (total_memory / num_chunks);
        l = rand() % 512;
        page_list = many_pages[j];
        page = page_list + k;
        x = page->numbers[l];
    }
    return 0;
}

从我调用 cache_hits 到 cache_misses 的程序中,我们看到内存大小增加了 8 倍,执行时间增加了 5 倍。当我们运行这个程序时,你希望看到什么?它使用的内存是 cache_misses 的 32 倍,但内存访问次数相同。

mike@computer:~$ time ./page_misses
Bouncing through 2048 MB, 4096 bytes at a time
real    2m1.327s
user    1m56.483s
sys     0m0.588s
mike@computer:~$ 

它花费了 cache_misses 的 8 倍和 cache_hits 的 40 倍。这是在具有 4GB RAM 的计算机上。我在这个程序中使用了 50% 的 RAM,而 cache_misses 使用了 1.5%,cache_hits 使用了 0.2%。即使它没有用完我计算机的所有 RAM,它也变得非常慢。意义重大就足够了。

我希望这是一本关于如何诊断程序运行缓慢的问题的不错的入门读物。

【讨论】:

  • 在这种情况下你怎么能确定是磁盘 I/O?
  • 我不能。这是一个猜测。另一篇文章提到它有 300 万行和 40 列,平均每列 50 个字节。那是6GB。肯定不适合 4GB 机器上的 RAM。所以这是一个相当不错的猜测,但你是对的,仍然是一个猜测。
  • 50 字节?在 R 中,整数=4,数字=8,字符=4(32 位)或 8(64 位),因为字符串被缓存。所以最多3e6 * 40 * 8 / 1024^3 = 0.9GB + 添加到 R 全局缓存中的唯一字符串(如果有)的数量。 IIUC。
  • 好吧,AdamNYC 并没有给我们完整的表定义,所以我假设它还有更多的东西,只有整数、字符和字符串指针。他可以很容易地拥有一堆独特的字符串、日期和其他东西。此外,我的经验是,当您看到用户+系统时间和经过时间之间的这些巨大差距时,IO 是罪魁祸首。我会错吗?当然。
  • 我要提到的另一件事是,在内核中花费与在用户空间中一样多的时间是一个很大的危险信号,表明内核正在做很多工作。为什么内核会做这么多工作?如果您运行 time ls -l /usr/bin,您应该会看到在 user 和 sys 上花费的时间大致相等,并且比它们花费在总和上的时间要多得多。这是为什么?将东西推送到终端需要很多时间,这是 IO 时间。
猜你喜欢
  • 1970-01-01
  • 1970-01-01
  • 2011-10-18
  • 1970-01-01
  • 1970-01-01
  • 2014-03-26
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
相关资源
最近更新 更多