使用 usage 的进程/线程不可能 Cpu 时间

Impossible Cpu time for process / thread with rusage

我正在计算进程/线程使用的 cpu 时间与调用某个函数之间的增量。

我正在为进程 cpu 时间获取不可能的值,下一次调用返回更小的 cpu 时间,这是不可能的。

这是我用来计算 cpu 时间的代码:

  u64 CpuTime::calculateCpuTime(bool a_thread)
  {
    struct rusage l_rusage;
    int retVal;
    if(a_thread)
    {
      retVal = getrusage(1, &l_rusage); //1 = RUSAGE_THREAD
    }
    else
    {
      retVal = getrusage(0, &l_rusage); //0 = RUSAGE_SELF
    }
    ASSERT(retVal==0);

    u64 userUSeconds = (static_cast<u64>(l_rusage.ru_utime.tv_sec)*1000000)+
      (static_cast<u64>(l_rusage.ru_utime.tv_usec));

    u64 systemUSeconds = (static_cast<u64>(l_rusage.ru_stime.tv_sec)*1000000)+
      (static_cast<u64>(l_rusage.ru_stime.tv_usec));

    if(a_thread)
    {
      return userUSeconds + systemUSeconds;
    }
    return (userUSeconds + systemUSeconds) / ACE_OS::num_processors_online();
  }

此外计算检索它的函数是异步的,一次不能超过 1 个线程访问它。

这是不可能输出(过程)的例子:

2016/03/23 13:39:05.187 - #2 - 15471/15055 - ThreadDeltaCpuTime = 6000 ThreadCpuTime = 46756013 ProcessCpuTime = 39820759 deltaProcessCpuTime= 250

2016/03/23 13:39:05.386 - #2 - 15470/15055 - ThreadDeltaCpuTime = 5000 ThreadCpuTime = 46663013 ProcessCpuTime = 39699759 deltaProcessCpuTime = 18446744073709430616

delta 计算是一个简单的 newValue - oldValue,带有一个 unsigned int,它得出这些数字。

线程不可能输出示例:

2016/03/23 13:38:59.183 - #2 - 15472/15055 - ThreadDeltaCpuTime = 6000 ThreadCpuTime = 47541012 ProcessCpuTime = 39658134 deltaProcessCpuTime = 5250

2016/03/23 13:38:59.382 - #2 - 15472/15055 - ThreadDeltaCpuTime = 1844 6744073708557617 ThreadCpuTime = 46547013 ProcessCpuTime = 39663009 deltaProcessCpuTime = 4625

我把线程id加粗了,你也可以看到函数在第一个1后200ms执行了。

我正在寻找为什么会发生这种情况的线索,我也尝试使用 ACE_OS 用法,结果相同(有道理),我可以通过忽略 "bad" 来解决这个问题价值观,但我想知道为什么会这样。

编辑:

这是我进行实际打印的地方:

  u64 computeCpuTime()
  {
    u64 deltaCpuTime= CpuTime::getThreadDeltaCpuTime();
    u64 CpuTime= getThreadCpuTime();
    u64 ProcessCpuTime= getProcessCpuTime();
    u64 deltaProcessCpuTime= CpuTime::getProcessDeltaCpuTime();
    Log<<value(deltaCpuTime)<<value(CpuTime)<<value(ProcessCpuTime)<<value(deltaProcessCpuTime)<<endlog;
    return deltaCpuTime;
  }

以及此计算中使用的其余函数:

  u64 CpuTime::getThreadDeltaCpuTime()
  {
    pid_t thisThread = (pid_t) syscall (SYS_gettid);
    u64& val = m_threadsCpuMap[thisThread];
    u64 oldValue =val;
    val = calculateCpuTime(true);
    return val - oldValue;
  }

  u64 CpuTime::getProcessDeltaCpuTime()
  {
    u64 oldValue = m_processCpu;
    m_processCpu = calculateCpuTime(false);

    return m_processCpu - oldValue;
  }

  u64 getThreadCpuTime()
  {
    return CpuTime::calculateCpuTime(true);
  }

  u64 getProcessCpuTime()
  {
    return CpuTime::calculateCpuTime(false);
  }

执行系统调用 ("m_cpuTime") 的对象是单例对象,受互斥锁保护,一次只能有 1 个线程访问它。

它包含线程映射 cpu 使用情况,m_threadsCpuMap(用于增量),以及最后一个进程 cpu 使用情况,m_processCpu。

另一个编辑:

我通过一个简单的测试简化了它,使用单线程,删除了活动 cpu 的除法,我只检查进程 Cpu 时间,仍然无法得到结果.

更新后的函数如下:

测试:

for(int i = 0; i < 100000 ; i++)
{
  for(int k = 0; k < 1000000; k++)
    m = k % i;
    cpuTime = CpuTime::instance()->getProcessDeltaCpuTime();
}

测试中使用的函数:

  u64 CpuTime::getProcessDeltaCpuTime()
  {
    u64 oldValue = m_processCpu;
    m_processCpu = calculateCpuTime(eThisProcess);
   Log<<value(oldValue)<<value(m_processCpu)<value( m_processCpu - oldValue)<<endlog;
    return m_processCpu - oldValue;
  }

  u64 CpuTime::calculateCpuTime(int a_type)
  {
    struct rusage l_rusage;
    int retVal;
    if(a_type == eThisThread)
    {
      retVal = /*ACE_OS::*/getrusage(1, &l_rusage);
    }
    else
    {
      retVal = /*ACE_OS::*/getrusage(0, &l_rusage);
    }

    u64 userUSeconds = (static_cast<u64>(l_rusage.ru_utime.tv_sec)*1000000)+
      (static_cast<u64>(l_rusage.ru_utime.tv_usec));

    u64 systemUSeconds = (static_cast<u64>(l_rusage.ru_stime.tv_sec)*100000)+
      (static_cast<u64>(l_rusage.ru_stime.tv_usec));

    if(a_type == eThisThread)
    {
      return userUSeconds + systemUSeconds;
    }
    return (userUSeconds + systemUSeconds)/* / ACE_OS::num_processors_online()*/;

这是一个日志示例,我已经删除了增量为 ~0 的所有时间

2016/03/29 08:07:05.198 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14797750 m_processCpu = 14798749 m_process Cpu - oldValue = 999

2016/03/29 08:07:05.199 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14798749 m_processCpu = 14799749 m_process Cpu - oldValue = 1000

2016/03/29 08:07:05.200 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14799749 m_processCpu = 14800749 m_process Cpu - oldValue = 1000

2016/03/29 08:07:05.201 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14800749 m_processCpu = 14801749 m_process Cpu - oldValue = 1000

2016/03/29 08:07:05.202 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14801749 m_processCpu = 14802749 m_process Cpu - oldValue = 1000

2016/03/29 08:07:05.203 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14802749 m_processCpu = 13903748 m_process Cpu - oldValue = 18446744073708652615

2016/03/29 08:07:05.204 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 13903748 m_processCpu = 13904748 m_process Cpu - oldValue = 1000

2016/03/29 08:07:05.205 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 13904748 m_processCpu = 13905748 m_process Cpu - oldValue = 1000

这次在 100000 次迭代中只有 1 次错误值。 在这之后,所有以下计算也更小,例如它是这样的: 1 2 3 4 5 6 7 8 9 10 错误值,6 7 8 9 10... 好像这个过程记不清了,回去了,然后正常继续。

又一次编辑:

我把代码分离了,完整的,尽量简单编译。而没有出现问题,可能是概率问题(之前是1/100000)。 这是代码:

int main()
{
  long int n = 0;
  long int oldValue = 0;
  long int newValue = 0;
  unsigned long int deltaValue = 0;

  for(int i = 0; i < 1000000; i++)
  {
    for(long int m = 0; m <10000; m++)
      n = m + i;
    struct rusage l_rusage;
    int retVal;
    retVal = getrusage(0, &l_rusage);
    if(retVal != 0) return 0;

    long int userUSeconds = l_rusage.ru_utime.tv_sec*1000000 + l_rusage.ru_utime.tv_usec;

    long int systemUSeconds = l_rusage.ru_stime.tv_sec*100000 + l_rusage.ru_stime.tv_usec;
    oldValue = newValue;
    newValue = userUSeconds + systemUSeconds;
    deltaValue = newValue - oldValue;
    if(deltaValue != 0)
      std::cout<<"Old value: "<< oldValue <<" New Value: "<< newValue <<" Delta value: "<<deltaValue<<"\n";


  }
  std::cout<<n;
  return 0;
}

通过进一步调查早期测试(使用我们的单元测试框架),问题总是在大约相同的 CPU 时间发生。 这意味着这是有原因的,我只是无法弄清楚在那个确切的时间发生了什么可能会导致这样的事情。 或者像这样的事情是怎么引起的。

我对 linux 内核不够熟悉,无法理解这个计算是如何进行的。

另一个见解 - 使用 clock() 获取进程时。它不会发生,甚至更多 - 似乎直到那一刻,值都大致相同,在这一点之后它们不是:

2016/03/29 12:36:19.158 - #2 - 20544/20544 - CpuTime::getProcessDeltaCpuTime: oldValue = 14598780 m_processCpu = 14598780 m_processCpu - oldValue = 0 oldClockTime = 14580000 m_clockTime = 14580000 m_clockTime - oldClockTime = 0

2016/03/29 12:36:19.158 - #2 - 20544/20544 - CpuTime::getProcessDeltaCpuTime: oldValue = 14598780 m_processCpu = 13699779 m_processCpu - oldValue = 18446744073708652615 oldClockTime = 14580000 m_clockTime = 14590000 m_clockTime - oldClockTime = 10000

2016/03/29 12:36:19.158 - #2 - 20544/20544 - CpuTime::getProcessDeltaCpuTime: oldValue = 13699779 m_processCpu = 13699779 m_processCpu - oldValue = 0 oldClockTime = 14590000 m_clockTime = 14590000 m_clockTime - oldClockTime = 0

这让我想到了另一个问题,usage 是如何计算的,clock() 是如何计算的?是什么导致了它们之间的差异?

我已经解决了这个问题,使用 clock_gettime 对其进行了测量,如果有任何人感兴趣,这里是代码:

  u64 CpuMeasure::calculateCpuTime(int a_type)
  {
    struct timespec ts;

    if(a_type == eThisThread)
    {
      if (ACE_OS::clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts) == 0)
      {
         return (u64)ts.tv_sec * 1000000 + (u64)ts.tv_nsec / 1000; //From nano to mili seconds
      }
    }
    else
    {
      if (ACE_OS::clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts) == 0)
      {
         return (u64)ts.tv_sec * 1000000 + (u64)ts.tv_nsec / 1000;
      }
    }
    ASSERT(false); //we cant be here, unless some thing bad happened
    return 0;
}

为了便携性,我正在使用 ACE_OS,但它适用于 sys/time.h

中的默认函数

然而,我仍然对 usage 奇怪的行为 有疑问,是什么导致它给出这些值。

仔细检查这些行:您将系统时间秒数乘以 10 万而不是 100 万:

u64 userUSeconds = (static_cast<u64>(l_rusage.ru_utime.tv_sec)*1000000)+
  (static_cast<u64>(l_rusage.ru_utime.tv_usec));

u64 systemUSeconds = (static_cast<u64>(l_rusage.ru_stime.tv_sec)*100000)+
  (static_cast<u64>(l_rusage.ru_stime.tv_usec));

您展示的三个示例中有两个(不是第一个)。

然而,这可以解释奇怪的序列:

2016/03/29 08:07:05.201 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14800749 m_processCpu = 14801749 m_process Cpu - oldValue = 1000

2016/03/29 08:07:05.202 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14801749 m_processCpu = 14802749 m_process Cpu - oldValue = 1000

2016/03/29 08:07:05.203 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 14802749 m_processCpu = 13903748 m_process Cpu - oldValue = 18446744073708652615

2016/03/29 08:07:05.204 - #2 - 24011/24011 - CpuTime::getProcessDeltaCpuTime: oldValue = 13903748 m_processCpu = 13904748 m_process Cpu - oldValue = 1000

每次迭代都会增加 1000 us。但我想一旦系统时间超过一秒,只增加 1/10 秒,导致 -0.9 秒偏移,正好是 14.8 -> 13.9 秒。

事实上:

 18446744073708652615 - 2^64 + 1 = -899000

即 -900000(0.9 秒)+ 1000 us