Zadałem poprzednie pytanie, aby spróbować wyodrębnić źródło wzrostu wykorzystania procesora podczas przenoszenia aplikacji z RHEL 5 na RHEL 6. Analiza, którą wykonałem, wydaje się wskazywać, że jest to spowodowane przez CFS w jądrze. Napisałem aplikację testową, aby spróbować sprawdzić, czy tak było (oryginalna aplikacja testowa została usunięta, aby zmieściła się w limicie rozmiaru, ale nadal jest dostępna w git repo) .
Skompilowałem go za pomocą następującego polecenia na RHEL 5:
cc test_select_work.c -O2 -DSLEEP_TYPE=0 -Wall -Wextra -lm -lpthread -o test_select_work
Następnie grałem z parametrami, aż czas wykonania jednej iteracji wynosił około 1 ms na Dell Precision m6500.
Mam następujący wynik na RHEL 5:
./test_select_work 1000 10000 300 4
time_per_iteration: min: 911.5 us avg: 913.7 us max: 917.1 us stddev: 2.4 us
./test_select_work 1000 10000 300 8
time_per_iteration: min: 1802.6 us avg: 1803.9 us max: 1809.1 us stddev: 2.1 us
./test_select_work 1000 10000 300 40
time_per_iteration: min: 7580.4 us avg: 8567.3 us max: 9022.0 us stddev: 299.6 us
I następujące informacje w RHEL 6:
./test_select_work 1000 10000 300 4
time_per_iteration: min: 914.6 us avg: 975.7 us max: 1034.5 us stddev: 50.0 us
./test_select_work 1000 10000 300 8
time_per_iteration: min: 1683.9 us avg: 1771.8 us max: 1810.8 us stddev: 43.4 us
./test_select_work 1000 10000 300 40
time_per_iteration: min: 7997.1 us avg: 8709.1 us max: 9061.8 us stddev: 310.0 us
W obu wersjach wyniki były mniej więcej takie, jak się spodziewałem, przy średnim czasie skalowania iteracji stosunkowo liniowo. Następnie skompilowałem ponownie -DSLEEP_TYPE=1
i otrzymałem następujące wyniki w RHEL 5:
./test_select_work 1000 10000 300 4
time_per_iteration: min: 1803.3 us avg: 1902.8 us max: 2001.5 us stddev: 113.8 us
./test_select_work 1000 10000 300 8
time_per_iteration: min: 1997.1 us avg: 2002.0 us max: 2010.8 us stddev: 5.0 us
./test_select_work 1000 10000 300 40
time_per_iteration: min: 6958.4 us avg: 8397.9 us max: 9423.7 us stddev: 619.7 us
I następujące wyniki na RHEL 6:
./test_select_work 1000 10000 300 4
time_per_iteration: min: 2107.1 us avg: 2143.1 us max: 2177.7 us stddev: 30.3 us
./test_select_work 1000 10000 300 8
time_per_iteration: min: 2903.3 us avg: 2903.8 us max: 2904.3 us stddev: 0.3 us
./test_select_work 1000 10000 300 40
time_per_iteration: min: 8877.7.1 us avg: 9016.3 us max: 9112.6 us stddev: 62.9 us
Na RHEL 5 wyniki były zgodne z oczekiwaniami (4 wątki trwają dwa razy dłużej z powodu snu 1 ms, ale 8 wątków zajmuje tyle samo czasu, ponieważ każdy wątek śpi teraz przez około połowę czasu, i wciąż dość dość wzrost liniowy).
Jednak w przypadku RHEL 6 czas potrzebny na 4 wątki zwiększył się o około 15% więcej niż oczekiwane podwojenie, a przypadek 8 wątków wzrósł o około 45% więcej niż oczekiwany niewielki wzrost. Wydaje się, że wzrost liczby przypadków z 4 wątkami polega na tym, że RHEL 6 śpi przez kilka mikrosekund dłużej niż 1 ms, podczas gdy RHEL 5 śpi tylko około 900 nas, ale to nie tłumaczy nieoczekiwanie dużego wzrostu liczby 8 i 40 skrzynki na nici.
Widziałem podobne typy zachowania ze wszystkimi wartościami 3 -DSLEEP_TYPE. Próbowałem także grać z parametrami harmonogramu w sysctl, ale nic nie miało znaczącego wpływu na wyniki. Wszelkie pomysły na dalszą diagnozę tego problemu?
AKTUALIZACJA: 07.05.2012
Dodałem pomiary zużycia procesora przez użytkownika i system z / proc / stat // tasks // stat jako dane wyjściowe testu, aby spróbować uzyskać inny punkt obserwacji. Znalazłem również problem ze sposobem aktualizacji średniej i odchylenia standardowego, który został wprowadzony, gdy dodałem zewnętrzną pętlę iteracji, więc dodam nowe wykresy, które mają skorygowane pomiary średniej i odchylenia standardowego. Zawarłem zaktualizowany program. Zrobiłem też repozytorium git, aby śledzić kod i jest on dostępny tutaj.
#include <limits.h>
#include <math.h>
#include <poll.h>
#include <pthread.h>
#include <sched.h>
#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <unistd.h>
#include <sys/select.h>
#include <sys/syscall.h>
#include <sys/time.h>
// Apparently GLIBC doesn't provide a wrapper for this function so provide it here
#ifndef HAS_GETTID
pid_t gettid(void)
{
return syscall(SYS_gettid);
}
#endif
// The different type of sleep that are supported
enum sleep_type {
SLEEP_TYPE_NONE,
SLEEP_TYPE_SELECT,
SLEEP_TYPE_POLL,
SLEEP_TYPE_USLEEP,
SLEEP_TYPE_YIELD,
SLEEP_TYPE_PTHREAD_COND,
SLEEP_TYPE_NANOSLEEP,
};
// Information returned by the processing thread
struct thread_res {
long long clock;
long long user;
long long sys;
};
// Function type for doing work with a sleep
typedef struct thread_res *(*work_func)(const int pid, const int sleep_time, const int num_iterations, const int work_size);
// Information passed to the thread
struct thread_info {
pid_t pid;
int sleep_time;
int num_iterations;
int work_size;
work_func func;
};
inline void get_thread_times(pid_t pid, pid_t tid, unsigned long long *utime, unsigned long long *stime)
{
char filename[FILENAME_MAX];
FILE *f;
sprintf(filename, "/proc/%d/task/%d/stat", pid, tid);
f = fopen(filename, "r");
if (f == NULL) {
*utime = 0;
*stime = 0;
return;
}
fscanf(f, "%*d %*s %*c %*d %*d %*d %*d %*d %*u %*u %*u %*u %*u %Lu %Lu", utime, stime);
fclose(f);
}
// In order to make SLEEP_TYPE a run-time parameter function pointers are used.
// The function pointer could have been to the sleep function being used, but
// then that would mean an extra function call inside of the "work loop" and I
// wanted to keep the measurements as tight as possible and the extra work being
// done to be as small/controlled as possible so instead the work is declared as
// a seriees of macros that are called in all of the sleep functions. The code
// is a bit uglier this way, but I believe it results in a more accurate test.
// Fill in a buffer with random numbers (taken from latt.c by Jens Axboe <jens.axboe@oracle.com>)
#define DECLARE_FUNC(NAME) struct thread_res *do_work_##NAME(const int pid, const int sleep_time, const int num_iterations, const int work_size)
#define DECLARE_WORK() \
int *buf; \
int pseed; \
int inum, bnum; \
pid_t tid; \
struct timeval clock_before, clock_after; \
unsigned long long user_before, user_after; \
unsigned long long sys_before, sys_after; \
struct thread_res *diff; \
tid = gettid(); \
buf = malloc(work_size * sizeof(*buf)); \
diff = malloc(sizeof(*diff)); \
get_thread_times(pid, tid, &user_before, &sys_before); \
gettimeofday(&clock_before, NULL)
#define DO_WORK(SLEEP_FUNC) \
for (inum=0; inum<num_iterations; ++inum) { \
SLEEP_FUNC \
\
pseed = 1; \
for (bnum=0; bnum<work_size; ++bnum) { \
pseed = pseed * 1103515245 + 12345; \
buf[bnum] = (pseed / 65536) % 32768; \
} \
} \
#define FINISH_WORK() \
gettimeofday(&clock_after, NULL); \
get_thread_times(pid, tid, &user_after, &sys_after); \
diff->clock = 1000000LL * (clock_after.tv_sec - clock_before.tv_sec); \
diff->clock += clock_after.tv_usec - clock_before.tv_usec; \
diff->user = user_after - user_before; \
diff->sys = sys_after - sys_before; \
free(buf); \
return diff
DECLARE_FUNC(nosleep)
{
DECLARE_WORK();
// Let the compiler know that sleep_time isn't used in this function
(void)sleep_time;
DO_WORK();
FINISH_WORK();
}
DECLARE_FUNC(select)
{
struct timeval ts;
DECLARE_WORK();
DO_WORK(
ts.tv_sec = 0;
ts.tv_usec = sleep_time;
select(0, 0, 0, 0, &ts);
);
FINISH_WORK();
}
DECLARE_FUNC(poll)
{
struct pollfd pfd;
const int sleep_time_ms = sleep_time / 1000;
DECLARE_WORK();
pfd.fd = 0;
pfd.events = 0;
DO_WORK(
poll(&pfd, 1, sleep_time_ms);
);
FINISH_WORK();
}
DECLARE_FUNC(usleep)
{
DECLARE_WORK();
DO_WORK(
usleep(sleep_time);
);
FINISH_WORK();
}
DECLARE_FUNC(yield)
{
DECLARE_WORK();
// Let the compiler know that sleep_time isn't used in this function
(void)sleep_time;
DO_WORK(
sched_yield();
);
FINISH_WORK();
}
DECLARE_FUNC(pthread_cond)
{
pthread_cond_t cond = PTHREAD_COND_INITIALIZER;
pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;
struct timespec ts;
const int sleep_time_ns = sleep_time * 1000;
DECLARE_WORK();
pthread_mutex_lock(&mutex);
DO_WORK(
clock_gettime(CLOCK_REALTIME, &ts);
ts.tv_nsec += sleep_time_ns;
if (ts.tv_nsec >= 1000000000) {
ts.tv_sec += 1;
ts.tv_nsec -= 1000000000;
}
pthread_cond_timedwait(&cond, &mutex, &ts);
);
pthread_mutex_unlock(&mutex);
pthread_cond_destroy(&cond);
pthread_mutex_destroy(&mutex);
FINISH_WORK();
}
DECLARE_FUNC(nanosleep)
{
struct timespec req, rem;
const int sleep_time_ns = sleep_time * 1000;
DECLARE_WORK();
DO_WORK(
req.tv_sec = 0;
req.tv_nsec = sleep_time_ns;
nanosleep(&req, &rem);
);
FINISH_WORK();
}
void *do_test(void *arg)
{
const struct thread_info *tinfo = (struct thread_info *)arg;
// Call the function to do the work
return (*tinfo->func)(tinfo->pid, tinfo->sleep_time, tinfo->num_iterations, tinfo->work_size);
}
struct thread_res_stats {
double min;
double max;
double avg;
double stddev;
double prev_avg;
};
#ifdef LLONG_MAX
#define THREAD_RES_STATS_INITIALIZER {LLONG_MAX, LLONG_MIN, 0, 0, 0}
#else
#define THREAD_RES_STATS_INITIALIZER {LONG_MAX, LONG_MIN, 0, 0, 0}
#endif
void update_stats(struct thread_res_stats *stats, long long value, int num_samples, int num_iterations, double scale_to_usecs)
{
// Calculate the average time per iteration
double value_per_iteration = value * scale_to_usecs / num_iterations;
// Update the max and min
if (value_per_iteration < stats->min)
stats->min = value_per_iteration;
if (value_per_iteration > stats->max)
stats->max = value_per_iteration;
// Update the average
stats->avg += (value_per_iteration - stats->avg) / (double)(num_samples);
// Update the standard deviation
stats->stddev += (value_per_iteration - stats->prev_avg) * (value_per_iteration - stats->avg);
// And record the current average for use in the next update
stats->prev_avg= stats->avg;
}
void print_stats(const char *name, const struct thread_res_stats *stats)
{
printf("%s: min: %.1f us avg: %.1f us max: %.1f us stddev: %.1f us\n",
name,
stats->min,
stats->avg,
stats->max,
stats->stddev);
}
int main(int argc, char **argv)
{
if (argc <= 6) {
printf("Usage: %s <sleep_time> <outer_iterations> <inner_iterations> <work_size> <num_threads> <sleep_type>\n", argv[0]);
printf(" outer_iterations: Number of iterations for each thread (used to calculate statistics)\n");
printf(" inner_iterations: Number of work/sleep cycles performed in each thread (used to improve consistency/observability))\n");
printf(" work_size: Number of array elements (in kb) that are filled with psuedo-random numbers\n");
printf(" num_threads: Number of threads to spawn and perform work/sleep cycles in\n");
printf(" sleep_type: 0=none 1=select 2=poll 3=usleep 4=yield 5=pthread_cond 6=nanosleep\n");
return -1;
}
struct thread_info tinfo;
int outer_iterations;
int sleep_type;
int s, inum, tnum, num_samples, num_threads;
pthread_attr_t attr;
pthread_t *threads;
struct thread_res *res;
struct thread_res **times;
// Track the stats for each of the measurements
struct thread_res_stats stats_clock = THREAD_RES_STATS_INITIALIZER;
struct thread_res_stats stats_user = THREAD_RES_STATS_INITIALIZER;
struct thread_res_stats stats_sys = THREAD_RES_STATS_INITIALIZER;
// Calculate the conversion factor from clock_t to seconds
const long clocks_per_sec = sysconf(_SC_CLK_TCK);
const double clocks_to_usec = 1000000 / (double)clocks_per_sec;
// Get the parameters
tinfo.pid = getpid();
tinfo.sleep_time = atoi(argv[1]);
outer_iterations = atoi(argv[2]);
tinfo.num_iterations = atoi(argv[3]);
tinfo.work_size = atoi(argv[4]) * 1024;
num_threads = atoi(argv[5]);
sleep_type = atoi(argv[6]);
switch (sleep_type) {
case SLEEP_TYPE_NONE: tinfo.func = &do_work_nosleep; break;
case SLEEP_TYPE_SELECT: tinfo.func = &do_work_select; break;
case SLEEP_TYPE_POLL: tinfo.func = &do_work_poll; break;
case SLEEP_TYPE_USLEEP: tinfo.func = &do_work_usleep; break;
case SLEEP_TYPE_YIELD: tinfo.func = &do_work_yield; break;
case SLEEP_TYPE_PTHREAD_COND: tinfo.func = &do_work_pthread_cond; break;
case SLEEP_TYPE_NANOSLEEP: tinfo.func = &do_work_nanosleep; break;
default:
printf("Invalid sleep type: %d\n", sleep_type);
return -7;
}
// Initialize the thread creation attributes
s = pthread_attr_init(&attr);
if (s != 0) {
printf("Error initializing thread attributes\n");
return -2;
}
// Allocate the memory to track the threads
threads = calloc(num_threads, sizeof(*threads));
times = calloc(num_threads, sizeof(*times));
if (threads == NULL) {
printf("Error allocating memory to track threads\n");
return -3;
}
// Initialize the number of samples
num_samples = 0;
// Perform the requested number of outer iterations
for (inum=0; inum<outer_iterations; ++inum) {
// Start all of the threads
for (tnum=0; tnum<num_threads; ++tnum) {
s = pthread_create(&threads[tnum], &attr, &do_test, &tinfo);
if (s != 0) {
printf("Error starting thread\n");
return -4;
}
}
// Wait for all the threads to finish
for (tnum=0; tnum<num_threads; ++tnum) {
s = pthread_join(threads[tnum], (void **)(&res));
if (s != 0) {
printf("Error waiting for thread\n");
return -6;
}
// Save the result for processing when they're all done
times[tnum] = res;
}
// For each of the threads
for (tnum=0; tnum<num_threads; ++tnum) {
// Increment the number of samples in the statistics
++num_samples;
// Update the statistics with this measurement
update_stats(&stats_clock, times[tnum]->clock, num_samples, tinfo.num_iterations, 1);
update_stats(&stats_user, times[tnum]->user, num_samples, tinfo.num_iterations, clocks_to_usec);
update_stats(&stats_sys, times[tnum]->sys, num_samples, tinfo.num_iterations, clocks_to_usec);
// And clean it up
free(times[tnum]);
}
}
// Clean up the thread creation attributes
s = pthread_attr_destroy(&attr);
if (s != 0) {
printf("Error cleaning up thread attributes\n");
return -5;
}
// Finish the calculation of the standard deviation
stats_clock.stddev = sqrtf(stats_clock.stddev / (num_samples - 1));
stats_user.stddev = sqrtf(stats_user.stddev / (num_samples - 1));
stats_sys.stddev = sqrtf(stats_sys.stddev / (num_samples - 1));
// Print out the statistics of the times
print_stats("gettimeofday_per_iteration", &stats_clock);
print_stats("utime_per_iteration", &stats_user);
print_stats("stime_per_iteration", &stats_sys);
// Clean up the allocated threads and times
free(threads);
free(times);
return 0;
}
Ponownie przeprowadziłem testy na Dell Vostro 200 (dwurdzeniowy procesor) z kilkoma różnymi wersjami systemu operacyjnego. Zdaję sobie sprawę, że kilka z nich będzie miało różne łatki i nie będzie to „czysty kod jądra”, ale był to najprostszy sposób, w jaki mogłem uruchomić testy na różnych wersjach jądra i uzyskać porównania. Wygenerowałem działki z gnuplot i załączyłem wersję z Bugzilli na ten temat .
Wszystkie te testy zostały uruchomione przy użyciu następującego polecenia z następującym skryptem i tym poleceniem ./run_test 1000 10 1000 250 8 6 <os_name>
.
#!/bin/bash
if [ $# -ne 7 ]; then
echo "Usage: `basename $0` <sleep_time> <outer_iterations> <inner_iterations> <work_size> <max_num_threads> <max_sleep_type> <test_name>"
echo " max_num_threads: The highest value used for num_threads in the results"
echo " max_sleep_type: The highest value used for sleep_type in the results"
echo " test_name: The name of the directory where the results will be stored"
exit -1
fi
sleep_time=$1
outer_iterations=$2
inner_iterations=$3
work_size=$4
max_num_threads=$5
max_sleep_type=$6
test_name=$7
# Make sure this results directory doesn't already exist
if [ -e $test_name ]; then
echo "$test_name already exists";
exit -1;
fi
# Create the directory to put the results in
mkdir $test_name
# Run through the requested number of SLEEP_TYPE values
for i in $(seq 0 $max_sleep_type)
do
# Run through the requested number of threads
for j in $(seq 1 $max_num_threads)
do
# Print which settings are about to be run
echo "sleep_type: $i num_threads: $j"
# Run the test and save it to the results file
./test_sleep $sleep_time $outer_iterations $inner_iterations $work_size $j $i >> "$test_name/results_$i.txt"
done
done
Oto podsumowanie tego, co zaobserwowałem. Tym razem porównuję je parami, ponieważ uważam, że w ten sposób jest to bardziej pouczające.
CentOS 5.6 vs CentOS 6.2
Czas zegara ściennego (gettimeofday) na iterację w CentOS 5.6 jest bardziej zróżnicowany niż 6.2, ale ma to sens, ponieważ CFS powinien wykonać lepszą pracę, zapewniając procesom równy czas procesora, co zapewni bardziej spójne wyniki. Jest również całkiem jasne, że CentOS 6.2 jest bardziej dokładny i spójny pod względem czasu, w którym śpi z różnymi mechanizmami spania.
„Kara” jest zdecydowanie widoczna w wersji 6.2 z małą liczbą wątków (widoczna na wykresach czasu gettimeofday i użytkownika), ale wydaje się, że jest zmniejszona dzięki większej liczbie wątków (różnica czasu użytkownika może być po prostu kwestią księgową, ponieważ pomiary czasu użytkownika są takie oczywiste).
Wykres czasowy systemu pokazuje, że mechanizmy uśpienia w wersji 6.2 zużywają więcej systemu niż w wersji 5.6, co odpowiada poprzednim wynikom prostego testu 50 procesów, który wywołał wybranie zużywającej nietrywialną ilość procesora na wersji 6.2, ale nie 5.6 .
Uważam, że warto zauważyć, że użycie harmonogramu_yield () nie wywołuje takiej samej kary jak w przypadku metod uśpienia. Wnioskuję z tego, że źródłem problemu nie jest sam program planujący, ale problem stanowi interakcja metod uśpienia z programem planującym.
Ubuntu 7.10 vs Ubuntu 8.04-4
Różnica w wersji jądra między tymi dwoma jest mniejsza niż w CentOS 5.6 i 6.2, ale nadal obejmują one okres, w którym wprowadzono CFS. Pierwszym interesującym rezultatem jest to, że selekcja i ankieta wydają się być jedynymi mechanizmami uśpienia, które mają „karę” w dniu 8.04, i że kara ta jest nadal większa niż w przypadku CentOS 6.2.
Czas użytkownika na wybranie i wybranie ankiety oraz Ubuntu 7.10 jest nieuzasadniony niski, więc wydaje się, że był to jakiś problem księgowy, który istniał wtedy, ale uważam, że nie ma on związku z bieżącym problemem / dyskusją.
Wydaje się, że czas systemowy jest dłuższy w przypadku Ubuntu 8.04 niż w Ubuntu 7.10, ale różnica ta jest DALEKO mniejsza niż w przypadku CentOS 5.6 vs 6.2.
Uwagi na temat Ubuntu 11.10 i Ubuntu 12.04
Pierwszą rzeczą do odnotowania tutaj jest to, że wykresy dla Ubuntu 12.04 były porównywalne z tymi z 11.10, więc nie pokazują, aby zapobiec niepotrzebnej redundancji.
Ogólnie wykresy dla Ubuntu 11.10 pokazują ten sam rodzaj trendu, który zaobserwowano w CentOS 6.2 (co wskazuje, że jest to ogólnie problem jądra, a nie tylko problem RHEL). Jedynym wyjątkiem jest to, że czas systemowy wydaje się być nieco wyższy w Ubuntu 11.10 niż w CentOS 6.2, ale po raz kolejny rozdzielczość tego pomiaru jest bardzo oczywista, więc myślę, że wszelkie wnioski inne niż „wydaje się być nieco wyższe „wchodziłby na cienki lód.
Ubuntu 11.10 vs Ubuntu 11.10 z BFS
Umowę PPA, która używa BFS z jądrem Ubuntu, można znaleźć na stronie https://launchpad.net/~chogydan/+archive/ppa i została zainstalowana w celu wygenerowania tego porównania. Nie mogłem znaleźć łatwego sposobu na uruchomienie CentOS 6.2 z BFS, więc zacząłem z tym porównaniem, a ponieważ wyniki Ubuntu 11.10 wypadają tak dobrze z CentOS 6.2, uważam, że jest to uczciwe i znaczące porównanie.
Najważniejsze jest to, że przy BFS tylko wybieranie i nanosypianie indukują „karę” przy małej liczbie wątków, ale wydaje się, że indukuje podobną „karę” (jeśli nie większą), jak w przypadku CFS dla wyższej Liczba wątków.
Innym interesującym punktem jest to, że czas systemowy wydaje się być krótszy w przypadku BFS niż w przypadku CFS. Po raz kolejny zaczyna to krążyć na cienkim lodzie z powodu gruboziarnistości danych, ale wydaje się, że istnieje pewna różnica, a wynik ten jest zgodny z prostym testem pętli wyboru procesu 50, który wykazał mniejsze zużycie procesora w BFS niż w CFS .
Wniosek, który wyciągam z tych dwóch punktów, jest taki, że BFS nie rozwiązuje problemu, ale przynajmniej wydaje się zmniejszać jego wpływ w niektórych obszarach.
Wniosek
Jak już wspomniano, nie sądzę, że jest to problem z samym harmonogramem, ale z interakcją między mechanizmami spania i harmonogramem. Uważam, że to zwiększone użycie procesora w procesach, które powinny spać i używają mało procesora, to regresja z CentOS 5.6 i główna przeszkoda dla każdego programu, który chce użyć pętli zdarzeń lub mechanizmu odpytywania.
Czy są jakieś inne dane lub testy, które mogę uruchomić, aby pomóc w dalszej diagnozie problemu?
Aktualizacja 29 czerwca 2012 r
Uprościłem trochę program testowy i można go znaleźć tutaj (post zaczynał przekraczać limit długości, więc musiałem go przenieść).