[Linux, C/C++] Problem mit Festplattenzugriffen

[Corrail]

Hallo!

Ich habe ein Problem mit Festplattenzugriffen in unserer Software, geschrieben in C/C++. Um es kurz auf den Punkt zu bringen: es passiert manchmal, dass wenn ich Daten auf die Festplatte schreibe (Größe von ca. 0.5MB) eine Festplattenoperation bis zu 10 Sekunden lang dauert und dadurch auch andere Threads, die in dieser Zeit ebenfalls was auf der Festplatte machen (simples logging) aufgehalten werden. Da es sich um eine Echtzeitapplikation handelt ist die Verzögerung in den Threads, die loggen tötlich.

Ich habe das Problem mit folgender Testapplikation nachstellen können:

#include <iostream>
#include <fstream>
#include <sstream>
#include <pthread.h>
#include <sys/time.h>

using namespace std;
#define DURATION_OF_DAY 86400000000LL

const int size_per_step = 30000;
const int num_steps = 15;
const int sleep_time = 80000;
const int64_t bad_time = 80000;
const int num_threads = 1;

const int logging_sleep_time = 50000;
const int64_t bad_logging_time = 10000;

int64_t getTime()
{
struct timeval tval;
gettimeofday(&tval, NULL);
int64_t micros = tval.tv_sec * 1000000LL + tval.tv_usec;
return micros;
}

string time2string(int64_t micros)
{
micros = micros % DURATION_OF_DAY;

int hour = ((micros / 1000000LL) / 3600 + 2) % 24; // +2 because of local and summer time
int min = micros / (60*1000000LL) % 60;
int sec = (micros / 1000000LL) % 60;
int ms = (micros / 1000LL) % 1000LL;

stringstream s;
s << hour << ":" << min << ":" << sec << "-" << ms;
return s.str();
}

void * logging(void * data)
{
fstream log_file("main_logging.log", ios_base::out | ios_base::binary);

int64_t last_time = getTime();

for (;;)
{
int64_t cur = getTime();
string tmp = time2string( cur );
int64_t diff = cur - last_time - logging_sleep_time;

int64_t t = getTime();
log_file << tmp << " " << diff << endl;
int64_t time = getTime() - t;
if (time > bad_logging_time)
cout << time2string(t) << " LOGGING_THREAD: logging took " << time << " usec" << endl;

last_time = cur;
usleep(logging_sleep_time);
}
}

void * file_writing(void * data)
{
char * buffer = new char[size_per_step];
fstream * file = 0;

int thread_num = *((int*)(data));

int i = 0;
int64_t time_sum = 0;
for (int i = 0;;++i)
{
if (i%num_steps == 0)
{
if (file)
{
time_sum = 0;
int64_t t = getTime();
delete file;
int64_t time = getTime() - t;
time_sum += time;
if (time > bad_time)
cout << time2string(t) << " THREAD" << thread_num << ": closing file " << i/num_steps-1 << " took " << time << " usec" << endl;
}

stringstream filename;
filename << "log/thread_" << thread_num << "_" << i/num_steps;
int64_t t = getTime();
file = new fstream(filename.str().c_str(), ios_base::out | ios_base::binary);
int64_t time = getTime() - t;
time_sum += time;
if (time > bad_time)
cout << time2string(t) << " THREAD" << thread_num << ": opening file " << i/num_steps << " took " << time << " usec" << endl;
}

int64_t t = getTime();
file->write(buffer, size_per_step );
int64_t time = getTime() - t;
time_sum += time;
if (time > bad_time)
cout << time2string(t) << " THREAD" << thread_num << ": Writing " << size_per_step << " byte took " << time << " usec" << endl;
usleep(sleep_time);
}

}

pthread_t start_thread(void * (*thread_function)(void*), void * data)
{
pthread_t thr;

pthread_attr_t attr;
pthread_attr_init(&attr);

pthread_attr_setdetachstate( &attr, PTHREAD_CREATE_JOINABLE );

pthread_create(&thr, &attr, thread_function, data);
pthread_attr_destroy(&attr);

return thr;
}

int main()
{
int * tmp = new int[num_threads];
for (int i = 0; i < num_threads; ++i)
{
tmp[i] = i;
start_thread(file_writing, tmp+i);
}

start_thread(logging, NULL);

for (;;)
usleep(1000000);

return 0;
}


Die Testapplikation erzeugt einen Thread, der 30000 Byte in eine Datei schreibt und dann 80ms lang schläft. Wenn er 15 mal diesen Block in eine Datei schreibt, so wird die aktuelle Datei geschlossen und eine neue Datei geöffnet. Zusätzlich wird ein Logging-Thread erzeugt, der 20 mal pro Sekunde auf die Festplatte loggt.

Bei einer Variante der Testapplikation, wo kein Logging-Thread, aber 2 file_writing Thread erzeugt werden tritt das Problem durchschnittlich ca. alle 3-8 Stunden auf und dürfte mit dem Festplattenfüllgrad zusammenhängen (ab ca. 60% Füllgrad beginnen die Probleme).

Bei einem Test (mit der oberen Testapplikation) ist nach 15 Stunden das erste mal so ein "Festplatten-Freeze" aufgetreten. Beide Threads waren jeweils eine halbe Sekunde blockiert. Das Problem tritt auf mehrere Hardwareplatformen und mehrere Distributionen auf. Auch bei den Dateisystemen wurde schon EXT3, RaiserFS und XFS getestet, ohne Erfolg. Ich hab diese Testapplikation auch auf die C lib (stdio..h) umgeschrieben, wo das Problem subjektiv nicht so stark auftritt, aber trotzdem vorhanden ist.

Ich bin für jeden Tipp/für jede Hilfe sehr dankbar!!

Liebe Grüße
Florian

[Ectoplasma]

Hallo Florian,

bei I/O Operationen kann es dir immer passieren, dass die anzusprechende Resource geblockt sein kann. Das Logging würde ich daher zweiteilig machen. Was du benötigst ist eine Queue für die Daten, die geloggt werden sollen. Die Logging-Function, z.B. "log(void *pData, int size)", nimmt Daten entgegen und packt diese über einen geeigneten Synchronisationsmechanismus in eine Queue. Auf der anderen Seite der Queue hast du einen Thread, der die Daten aus der Queue heraus nimmt und auf Platte schreibt. Auf diese Weise erreichts du ein Echtzeit-Logging, was den Aufruf der "log" Funktion anbelangt.

Sollen die zu loggenden Daten ebenfalls in Echtzeit auf der Platte landen, hast du eh ein Problem. Mit einem normalen OS kannst du das jedenfalls abhaken. Ich denke aber die oben beschriebene Lösung sollte reichen.

[Corrail]

Hallo!

Danke für die Antwort. Die Idee mit dem zusätzlichen Logging-Thread wäre mir eh auch schon gekommen, das Problem dabei ist, sobald die Applikation abstürzt, verlier ich dich noch gepufferten Logs.
Was mich nur verwundert ist, dass es Stundenlang ohne Probleme durchläuft, es dann aber manchmal zu so groben Aussetzern kommt.

[Ectoplasma]

Hallo!

Danke für die Antwort. Die Idee mit dem zusätzlichen Logging-Thread wäre mir eh auch schon gekommen, das Problem dabei ist, sobald die Applikation abstürzt, verlier ich dich noch gepufferten Logs.


Doofe Anwort von mir, aber die Anwendung soll ja auch nicht abstürzen. Ausserdem kann der logging thread ja rechtzeitig Daten flushen etc. Bei einem Absturz der Anwendung, können sowieso diverse Dinge passieren und verloren gehen. Ich würde mir an dieser Stelle eher Gedanken über einen eigenen Exception-Handler machen, wenn die Log-Information so wichtig sind.


Was mich nur verwundert ist, dass es Stundenlang ohne Probleme durchläuft, es dann aber manchmal zu so groben Aussetzern kommt.

Das kann ich dir auch nicht sagen, aber es hört sich so an, als ob stundenlang Daten in einem Cache liegen und dann erst auf Platte geflusht werden. Daraus kann natürlich das o.g. Problem entstehen. In deinem Code kann ich jedenfalls nichts grob fahrlässiges erkennen. Aber vielleicht entdeckt ein andere Member ja noch ein Problem in deinem Code.