Din*_*ari 6 c c++ linux multithreading ace
我正在计算进程/线程正在使用的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
增量计算是一个简单的newValue - oldValue,带有unsigned int,它会导致这些数字.
线程不可能输出的示例:
2016年3月23日13:38:59.183 - #2 - 15472 /15055 - ThreadDeltaCpuTime = 6000 ThreadCpuTime = 47541012 ProcessCpuTime = 39658134 deltaProcessCpuTime = 5250
2016年3月23日13:38:59.382 - #2 - 15472 /15055 - ThreadDeltaCpuTime = 1844 6744073708557617 ThreadCpuTime = 46547013 ProcessCpuTime = 39663009 deltaProcessCpuTime = 4625
我已经加粗了线程ID,你也可以看到该函数已经在第一个1之后执行了200ms.
我正在寻找一个线索,为什么会发生这种情况,我也试过使用ACE_OS rusage,结果相同(有意义),我可以通过忽略"坏"值来解决这个问题,但我想知道为什么会发生这种情况.
编辑:
这是我实际打印的地方:
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(用于delta),以及最后一个进程cpu用法m_processCpu.
另一个编辑:
我通过简单的测试简化了它,使用单个线程,通过活动cpu删除了除法,并且只检查Process 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()*/;
这是日志的一个例子,我已经删除了delta为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 ......好像过程丢失了,回去了,然后继续正常.
YET ANOUTHER编辑:
我完全分开了代码,尽可能简单地编译它.问题没有发生,可能是概率问题(以前是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
这引出了一个不同的问题,如何计算rusage,以及clock()如何？什么可能导致他们之间的差异？
我已经解决了这个问题,使用clock_gettime测量它,如果有任何1感兴趣,这里是代码:
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中的默认函数
然而,我仍然对罗斯奇怪的行为提出疑问,这可能会导致它给出这些价值观.
仔细检查这些行：您将系统时间秒乘以 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