C++. Чем вызвано увеличение времени выполнения функции в многопоточной программе?
Для примера есть вот такая функция:
auto lambda = [](int k)
{
size_t size = 1920 * 1080 * 3;
size_t repeatCount = 100;
char* ch = new char [size];
auto start = std::chrono::high_resolution_clock::now();
for (int i = 0; i < repeatCount; ++i)
{
for (int j = 0; j < size; ++j)
{
ch[j] = j % 255;
}
}
auto duration = std::chrono::duration<double, std::milli>(std::chrono::high_resolution_clock::now() - start).count() / repeatCount;
std::cout << k << " " << std::this_thread::get_id() << " " << duration << std::endl << std::flush;
delete [] ch;
};
Среднее время её выполнения при наличии в программе лишь основного потока: 4.60426 мс
Далее выполняю данную функцию в n-ом числе потоков (в данном случае - 9):
std::vector <std::future <void>> futures;
for (int k = 0; k < 9; ++k)
{
futures.push_back(std::async(std::launch::async, lambda, k));
}
Времена соответсвенно:
6.66124
6.86142
6.96151
7.12166
7.31183
7.32184
7.33185
7.47198
7.51201
Почему возросло время выполнения? В моей машине 6 ядер, 12 потоков. Машина во время выполнения тестов ничего другого не делала (нагрузка процессора не превышала 80%)
CPU : Ryzen 3600X 6-Core
OS : Win10 x64
compiler : mingw x64
Опции компилятора: g++ -c -fno-keep-inline-dllexport -O2 -std=gnu++11 -Wall -Wextra -Wextra -fexceptions -mthreads -DUNICODE -D_UNICODE -DWIN32 -DMINGW_HAS_SECURE_API=1 -DQT_DEPRECATED_WARNINGS -DQT_NO_DEBUG -DQT_CORE_LIB
UPD. На всякий случай минимально воспроизводимый пример:
#include <iostream>
#include <chrono>
#include <thread>
#include <vector>
#include <future>
int main(int argc, char *argv[])
{
auto lambda = [](int k)
{
size_t size = 1920 * 1080 * 3;
size_t repeatCount = 100;
char* ch = new char [size];
auto start = std::chrono::high_resolution_clock::now();
for (int i = 0; i < repeatCount; ++i)
{
for (int j = 0; j < size; ++j)
{
ch[j] = j % 255;
}
}
auto duration = std::chrono::duration<double, std::milli>(std::chrono::high_resolution_clock::now() - start).count() / repeatCount;
std::cout << k << " " << std::this_thread::get_id() << " " << duration << std::endl << std::flush;
delete [] ch;
};
lambda(-1);
std::vector <std::future <void>> futures;
for (int k = 0; k < 9; ++k)
{
futures.push_back(std::async(std::launch::async, lambda, k));
}
return 0;
}
UPD 2: использование сырых тредов не меняет ситуации:
std::vector <std::thread> threads;
for (int k = 0; k < 9; ++k)
{
threads.push_back(std::move(std::thread(lambda, k)));
}
for (auto& thread : threads)
{
thread.join();
}
5.20472
6.15558
6.22565
6.59598
6.67605
6.68598
6.73603
7.50681
7.52675
Ответы (3 шт):
Это не ответ на вопрос, а скорее ответ @avp на предложение запустить в обычных потоках
А если просто запустить аналогичную функцию в 9-ти потоках (без всяких прибамбасов, типа future, async, launch ...)?
Я, как очень ленивый человек, решил попробовать вместо обычных потоков OpenMP (думаю, тут не будет принципиальных отличий). И еще, немного изменил программу: cout довольно неприлично ведет себя при выводе из нескольких потоков одновременно (выводит кашу из чисел), поэтому я для вывода использую printf(). Вот модифицированный код примера:
#include <iostream>
#include <chrono>
#include <thread>
#include <vector>
#include <future>
#include <cstdio>
#include <omp.h>
#include <sstream>
int main()
{
const int n_threads = 8;
auto lambda = [](int k)
{
size_t size = 1920 * 1080 * 3;
size_t repeatCount = 100;
char* ch = new char [size];
std::stringstream ss;
ss << std::this_thread::get_id();
auto start = std::chrono::high_resolution_clock::now();
for (size_t i = 0; i < repeatCount; ++i)
{
for (size_t j = 0; j < size; ++j)
{
ch[j] = j % 255;
}
}
auto duration = std::chrono::duration<double, std::milli>(std::chrono::high_resolution_clock::now() - start).count() / repeatCount;
//std::cout << k << "\tThread id:" << std::this_thread::get_id() << "\tTime: " << duration << " ms" << std::endl; /// << std::flush;
std::printf("k = %d\tThread id: %s\tTime: %lf ms\n",k, ss.str().c_str(),duration);
/// std::printf("k = %d\tThread id: %d\tTime: %lf ms\n",k, omp_get_thread_num(),duration);
delete [] ch;
};
std::printf("Linear version:\n");
lambda(-1);
std::printf("\nAsync version:\n");
std::vector <std::future <void>> futures;
for (int k = 0; k < n_threads; ++k)
{
futures.push_back(std::async(std::launch::async, lambda, k));
}
for (int k = 0; k < n_threads; ++k)
futures[k].wait();
printf("\n\nOMP version:\n");
#pragma omp parallel for num_threads(n_threads)
for (int k = 0; k < n_threads; ++k)
{
lambda(k);
}
return 0;
}
Программу собирал командой: g++ -O2 -Wall -o "futures" "futures.cpp" -fopenmp -pedantic -Wextra, компилятор GCC: gcc version 7.3.0 (x86_64-posix-seh-rev0, Built by MinGW-W64 project).
У меня 4-х ядерный Core i5, поэтому оптимальным для него было бы 4 потока... Но почему-то нет. Даже при 4-х потоках время выполнения <измеряемой части> функции в асинхронных потоках чуть больше, чем при однократном запуске функции. И только при двух потоках это время получается одинаковым.
Привожу пример расчетов для 8 потоков (время при асинхронных вызовах растет от количества потоков, но не линейно: при 100 потоках время было в диапазоне от 20 до 35мс для разных потоков).
PS: с асинхронными потоками раньше дел не имел, поэтому сильно не пинайте, если не верно понял идею методов wait() с ожиданием завершения всех таких потоков :-).
UPD: заметил, что не изменяю количество потоков для OpenMP (по-умолчанию, OpenMP задет количество потоков равным количеству логических процессоров, т.е. у меня было всё время 4). Добавил в директиву num_threads(n_threads) и всё стало заметно хуже: для обычных потоков время выполнения блока тоже растет. Так что, вопрос остается открытым: что не так с тем тестируемым блоком кода и параллельными потоками?.. По идее, размер кванта времени в windows 10 должен быть около 25-30 мс, т.е. переключение потоков не должно бы мешать выполнению блока кода, "длиной" в 5 мс... Есть подозрение, что мы наблюдаем "квантовые эффекты", когда сам наблюдатель вносит изменения в эксперимент. Мы для измерения времени используем внутренний высокоточный таймер процессора из разных потоков одновременно - не он ли всё тормозит? Сколько "одновременных" таймеров может нам выделить CPU? И возможно, этот таймер работает через мютекс (допускаю даже, что он аппаратный).
UPD2: Из интереса, попробовал 100 потоков снова (с исправленной директивой для указания количества потоков). И тут оказалось, что OpenMP очень сильно проигрывает: у него получается время 135 мс (в среднем, диапазон от 130 до 140) против 30 мс с async. Наверное, нужно таки и честные потоки проверить.
Это пока тоже не ответ на вопрос. Я так же заинтересовался этим вопросом и решил поэкспериментировать. Для чистоты эксперимента я модифицировал, вернее почти полностью переписал код, постаравшись убрать все моменты, которые могли бы влиять на увеличение времени выполнения потоков, а именно: 1) отказался от использования библиотек std в пользу прямой работы с WinAPI; 2) синхронизировал потоки таким образрм, чтобы измеряемый цикл начинал выполнялся только после того, как запустятся все потоки, а сами потоки не завершались прежде, чем завершится последний цикл; 3) операторы new[], delete[] и вывод результатов вынес за пределы функции потока. Также добавил информативности в вывод.
В общем, вот код:
#include <iostream>
#include <assert.h>
#include <windows.h>
#define NUM_THREADS 12
#define DATA_SIZE (1920*1080*3)
#define MESURE_COUNT 100
#define INLINE __attribute__ ((always_inline)) inline
INLINE int GetCpuCoreId()
{
int cpu_core_id;
asm (
".intel_syntax noprefix\n"
" rdtscp \n"
" mov %0,ecx \n"
:"=rm"(cpu_core_id)
:
:"eax","edx","ecx"
);
return cpu_core_id;
}
#define MS_PER_TICKS 0.0001
class CTimer
{
union _TIME
{
FILETIME fileTime;
long long qwTime;
};
typedef void WINAPI(*_PFN_GSTPAFT)(LPFILETIME lpSystemTimeAsFileTime);
static _PFN_GSTPAFT s_pfnGetSystemTimePreciseAsFileTime;
_TIME m_StartTime;
_TIME m_CurrentTime;
public:
static INLINE bool GlobalInit()
{
HINSTANCE hKernel32 = GetModuleHandle("kernel32.dll");
if (hKernel32)
{
s_pfnGetSystemTimePreciseAsFileTime = (_PFN_GSTPAFT)GetProcAddress(hKernel32,"GetSystemTimePreciseAsFileTime");
if (s_pfnGetSystemTimePreciseAsFileTime) return true;
}
return false;
}
INLINE void Start()
{
assert (s_pfnGetSystemTimePreciseAsFileTime!=NULL);
s_pfnGetSystemTimePreciseAsFileTime(&m_StartTime.fileTime);
}
INLINE double GetTime()
{
assert (s_pfnGetSystemTimePreciseAsFileTime!=NULL);
s_pfnGetSystemTimePreciseAsFileTime(&m_CurrentTime.fileTime);
return (double)(m_CurrentTime.qwTime-m_StartTime.qwTime)*MS_PER_TICKS;
}
};
CTimer::_PFN_GSTPAFT CTimer::s_pfnGetSystemTimePreciseAsFileTime = NULL;
UINT volatile g_uNumThreads;
LONG volatile g_nThreadCount;
double g_lfBaseDuration = 0.0;
struct THREAD_TAG
{
//input data
char* pData;
HANDLE hThread;
//output data
DWORD dwThreadId;
int nPriority;
int nCpuCoreId;
double lfDuration;
INLINE THREAD_TAG()
{
pData = new char[DATA_SIZE];
}
INLINE ~THREAD_TAG()
{
delete[] pData;
}
};
void thread_func(THREAD_TAG* pTag);
double test_duration(char* pData, size_t uDataSize);
void write_thread_result(int nIndex, THREAD_TAG* pTag);
int main()
{
THREAD_TAG t1;
THREAD_TAG t[NUM_THREADS];
if (!CTimer::GlobalInit()) return -1; //need Win8 or higher
g_uNumThreads = 1;
g_nThreadCount = 0;
thread_func(&t1);
write_thread_result(-1,&t1);
puts("");
g_uNumThreads = NUM_THREADS;
g_nThreadCount = 0;
for (int i=0; i<NUM_THREADS; ++i)
t[i].hThread = CreateThread(NULL,0,(LPTHREAD_START_ROUTINE)thread_func,(LPVOID)&t[i],0,NULL);
for (int i=0; i<NUM_THREADS; ++i)
if (t[i].hThread) WaitForSingleObject(t[i].hThread,INFINITE);
double lfAvgDuration = 0;
for (int i = 0; i<NUM_THREADS; ++i)
{
write_thread_result(i,&t[i]);
lfAvgDuration+= t[i].lfDuration;
}
lfAvgDuration/= NUM_THREADS;
puts("");
std::cout << "average:\t\t\t\t\t\t"
<< lfAvgDuration << "\t(" << lfAvgDuration/g_lfBaseDuration*100 << "%)"
<< std::endl << std::flush;
return 0;
}
void thread_func(THREAD_TAG* pTag)
{
InterlockedIncrement(&g_nThreadCount);
while (g_nThreadCount<g_uNumThreads);
pTag->lfDuration = test_duration(pTag->pData,DATA_SIZE);
InterlockedDecrement(&g_nThreadCount);
while (g_nThreadCount>0);
if (g_lfBaseDuration==0.0) g_lfBaseDuration = pTag->lfDuration;
pTag->dwThreadId = GetCurrentThreadId();
pTag->nPriority = GetThreadPriority(GetCurrentThread());
pTag->nCpuCoreId = GetCpuCoreId();
};
double test_duration(char* pData, size_t uDataSize)
{
CTimer timer;
timer.Start();
for (int i = 0; i < MESURE_COUNT; ++i)
for (int j = 0; j < uDataSize; ++j)
pData[j] = j % 255;
return timer.GetTime()/MESURE_COUNT;
}
void write_thread_result(int nIndex, THREAD_TAG* pTag)
{
std::cout << nIndex << "\t\t" << pTag->dwThreadId
<< "\t(priority: " << pTag->nPriority << ", core: " << pTag->nCpuCoreId << ")\t\t"
<< pTag->lfDuration << "\t(" << pTag->lfDuration/g_lfBaseDuration*100 << "%)"
<< std::endl << std::flush;
}
А теперь результаты. У меня процессор AMD Ryzen 5 2600X, 6 физических ядер, 12 виртуальных.
Запустил программу с NUM_THREADS==6, и получил увеличение времени выполнения в среднем на 18% (при каждом запуске показатель варьировался где-то от 10% до 25%). Вот скрин:

Но при запуске с 12 потоками, всякий раз получал увеличение времени выполнения практически ровно в два раза, т.е. так, как по идее должно было быть, будь у меня ровно 6 ядер без гипертрединга:

В общем, какие у кого есть ещё идеи? Мои предположения: такое увеличение времени при параллельном выполнении может быть связано с конкуренцией за шину данных при обращениях к памяти, либо с какими-то эффектами от кэша. Но это только лишь предположения...
Мое предположение друзья, что все из за RAM и контроллера, он не дает возможности предоставить оперативку всем потокам одновременно. На RAM с двумя каналами пошло ускорение! Ну и как добавили - пресловутый кеш-коллектор.
