Дублирование выходного файла журнала производителя-потребителя

У меня возникли проблемы с реализацией проблемы «производитель-потребитель». Похоже, что он работает нормально по большей части, но когда я реализовал файл журнала для захвата критических событий, я понял, что произошло некоторое дублирование событий. Будет ли это из-за того, что манипуляции с файлами не являются взаимоисключающими или это может быть причиной чего-то другого? Я запускаю код на виртуальной машине Ubuntu 12.04.

#include <iostream>
#include <pthread.h>
#include <cstdlib>
#include <signal.h>
#include <unistd.h>
#include <time.h>
#include <stdio.h>
#include <sstream>
using namespace std;
string trimspace(string);
char* createString(string);
void* producer();
void* consumer();
void createArray(int);
int produceItem();
void createProducers(int);
void createConsumers(int);
void signalHandler(int);
int full=0;
int front=0;
int rear=0;
int empty;
int BUFFER_SIZE;
int producerCount;
int consumerCount;
int* buffer;
bool running;
FILE* logFile;
timespec pts;
timespec cts;
pthread_t* producers;
pthread_t* consumers;
pthread_mutex_t counter_mutex= PTHREAD_MUTEX_INITIALIZER;
pthread_mutex_t condp_mutex= PTHREAD_MUTEX_INITIALIZER;
pthread_mutex_t condc_mutex= PTHREAD_MUTEX_INITIALIZER;
pthread_cond_t condVarProd;
pthread_cond_t condVarCons;
int main()
{
running=true;
pthread_cond_init(&condVarCons,NULL);
pthread_cond_init(&condVarProd,NULL);
srand ( time(NULL) );
signal(SIGINT, signalHandler);
full=0;
BUFFER_SIZE=0;
string data;
cout<<"How many producers would you like to create? ";
getline(cin,data);
data=trimspace(data);
char* data2=createString(data);
producerCount=atoi(data2);
free (data2);
while (producerCount<=0){
cout<<"Please enter a valid number of producers to create! ";
getline(cin,data);
data=trimspace(data);
data2=createString(data);
producerCount=atoi(data2);
free (data2);
}
cout<<"How many consumers would you like to create? ";
getline(cin,data);
data=trimspace(data);
data2=createString(data);
consumerCount=atoi(data2);
free(data2);
while (consumerCount<=0){
cout<<"Please enter a valid number of consumers to create! ";
getline(cin,data);
data=trimspace(data);
data2=createString(data);
consumerCount=atoi(data2);
free (data2);
}cout<<"How large of a rotating buffer would you like to create? ";
getline(cin,data);
data=trimspace(data);
data2=createString(data);
BUFFER_SIZE=atoi(data2);
free(data2);
while (BUFFER_SIZE<=0){
cout<<"Please enter a valid buffer size to create! ";
getline(cin,data);
data=trimspace(data);
data2=createString(data);
BUFFER_SIZE=atoi(data2);
free (data2);
}
cout<<"What would you like to name your logfile? ";
getline (cin,data);
data=trimspace(data);
data2=createString(data);
logFile=fopen(data2,"a");
free(data2);
empty=BUFFER_SIZE;
createArray(BUFFER_SIZE);
int i;
createProducers(producerCount);
createConsumers(consumerCount);
for (i=0; i<producerCount;i++){
pthread_create(&producers[i], NULL, (void * (*)(void *))&producer, NULL);
}
for (i=0; i<consumerCount;i++){
pthread_create(&consumers[i], NULL, (void * (*)(void *))&consumer, NULL);
}
while(true);
return 0;
}
void createArray(int size){
if (!buffer){
buffer=(int*)malloc(size*sizeof(int));
}
}
void createProducers(int size){
if (!producers){
producers=(pthread_t*)malloc(size*sizeof(pthread_t*));
}
}
void createConsumers(int size){
if (!consumers){
consumers=(pthread_t*)malloc(size*sizeof(pthread_t*));
}
}
void * producer(){
pthread_setcanceltype(PTHREAD_CANCEL_ASYNCHRONOUS,NULL);
stringstream loginfo;
while (running){
pthread_mutex_lock(&condp_mutex); //sets mutual exclusion for the producer
clock_gettime(CLOCK_REALTIME,&pts);
loginfo<<pts.tv_nsec<<": Producer "<<pthread_self()<< "entered critical section.\n";
char* logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);
int item = produceItem();
//down(empty); //we will have one less empty slot when this is done
while (empty==0){
clock_gettime(CLOCK_REALTIME,&pts);
loginfo<<pts.tv_nsec<<": Producer "<<pthread_self()<<" encountered full buffer.\n";
logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);
pthread_cond_wait(&condVarProd,&condp_mutex);
}
//pthread_mutex_lock(&condp_mutex); //sets mutual exclusion for the producer
empty--;
buffer[rear]=item;
int rear2=rear;
rear=((rear+1)%BUFFER_SIZE);
clock_gettime(CLOCK_REALTIME,&pts);
loginfo<<pts.tv_nsec<<": Item created by "<<pthread_self()<<" into slot "<<rear2<<". Value: "<<item<<". \n";
logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);
//write to log file
full++;
pthread_cond_signal(&condVarCons);
clock_gettime(CLOCK_REALTIME,&pts);
loginfo<<pts.tv_nsec<<": Producer "<<pthread_self()<< "left critical section.\n";
logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);

pthread_mutex_unlock(&condp_mutex);
usleep(rand()%5000000);
//releases mutual exclusion for the producer
//up(full); //now that this is complete, we have one more full slot

//struct timespec req={(rand()%5000+1)*1000000},rem={0};
//nanosleep(&req, &rem); //sleeps for 1 millisecond - 5 seconds
}
}
void* consumer(){
pthread_setcanceltype(PTHREAD_CANCEL_ASYNCHRONOUS,NULL);
stringstream loginfo;
while (running){
//down (&full);
pthread_mutex_lock(&condc_mutex);
clock_gettime(CLOCK_REALTIME,&cts);
loginfo<<cts.tv_nsec<<": Consumer "<<pthread_self()<< "entered critical section.\n";
char* logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);
while (full==0){
clock_gettime(CLOCK_REALTIME,&cts);
loginfo<<cts.tv_nsec<<": Consumer "<<pthread_self()<<" encountered empty buffer.\n";
logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);
pthread_cond_wait(&condVarCons,&condc_mutex);
}
full--;
//pthread_mutex_lock(&condc_mutex);
int item=buffer[front];
int front2=front;
front=((front+1)%BUFFER_SIZE);

clock_gettime(CLOCK_REALTIME,&cts);
loginfo<<cts.tv_nsec<<": Item removed by "<<pthread_self()<<" from slot "<<front2<<". Value: "<<item<<". \n";
logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);

//write to log file
empty++;
pthread_cond_signal(&condVarProd);
clock_gettime(CLOCK_REALTIME,&cts);
loginfo<<cts.tv_nsec<<": Consumer "<<pthread_self()<< "left critical section.\n";
logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);
pthread_mutex_unlock(&condc_mutex);
//up(&empty);
usleep(rand()%5000000);
//struct timespec req={(rand()%5000+1)*1000000},rem={0};
//nanosleep(&req, &rem); //sleeps for 1 millisecond - 5 seconds
}
}
string trimspace(string str){ //trims leading and trailing space off string and returns new string
size_t startpos=str.find_first_not_of(" ");
size_t endpos=str.find_last_not_of(" ");
return str.substr(startpos, endpos-startpos+1);
}
char* createString(string str){ //converts a string to a c string using malloc
char* c=(char*)malloc(str.length()+1);
int i;
for (i=0;i<str.length();i++){
c[i]=str[i];
}
c[i]='\0';
return c;
}
int produceItem(){ //creates and returns an integer (item)
int item= rand()%1000000+1; //random int is between 1 and 1,000,000
return item;
}
void signalHandler( int signum )
{
if (signum==SIGINT){
running=false;
cout<<"\nEnding application... \n";
fclose(logFile);
//int i;

for (i=0;i<producerCount;i++){
pthread_cancel(producers[i]);
//pthread_join(producers[i],NULL);

}for (i=0;i<consumerCount;i++){
pthread_cancel(consumers[i]);
//pthread_join(consumers[i],NULL);
//}
exit(0);
}
}

Это привело к следующему в одном лог-файле на одном испытании. Как вы можете видеть, появляются повторяющиеся события, но, похоже, они работают нормально, поскольку порядок, в котором элементы создаются и удаляются (сравниваются метки времени с идентификатором потока, ячейкой буфера и значением, сохраненным / восстановленным):

390783278: Producer 139708484286208entered critical section.
390783278: Producer 139708484286208entered critical section.
391751560: Item created by 139708484286208 into slot 0. Value: 994902.
390783278: Producer 139708484286208entered critical section.
391751560: Item created by 139708484286208 into slot 0. Value: 994902.
391758681: Producer 139708484286208left critical section.
391766506: Producer 139708475893504entered critical section.
391766506: Producer 139708475893504entered critical section.
391788442: Item created by 139708475893504 into slot 1. Value: 452289.
391766506: Producer 139708475893504entered critical section.
391788442: Item created by 139708475893504 into slot 1. Value: 452289.
391790768: Producer 139708475893504left critical section.
391799767: Producer 139708492678912entered critical section.
391799767: Producer 139708492678912entered critical section.
391807766: Item created by 139708492678912 into slot 2. Value: 775797.
391799767: Producer 139708492678912entered critical section.
391807766: Item created by 139708492678912 into slot 2. Value: 775797.
391809898: Producer 139708492678912left critical section.
391815624: Producer 139708425537280entered critical section.
391815624: Producer 139708425537280entered critical section.
391824889: Item created by 139708425537280 into slot 3. Value: 40803.
391815624: Producer 139708425537280entered critical section.
391824889: Item created by 139708425537280 into slot 3. Value: 40803.
391827189: Producer 139708425537280left critical section.
391832787: Producer 139708442322688entered critical section.
391832787: Producer 139708442322688entered critical section.
391839933: Item created by 139708442322688 into slot 4. Value: 859933.
391832787: Producer 139708442322688entered critical section.
391839933: Item created by 139708442322688 into slot 4. Value: 859933.
391842089: Producer 139708442322688left critical section.
391847512: Producer 139708433929984entered critical section.
391847512: Producer 139708433929984entered critical section.
391857473: Item created by 139708433929984 into slot 5. Value: 862962.
391847512: Producer 139708433929984entered critical section.
391857473: Item created by 139708433929984 into slot 5. Value: 862962.
391859600: Producer 139708433929984left critical section.
391865631: Producer 139708417144576entered critical section.
391865631: Producer 139708417144576entered critical section.
391872901: Item created by 139708417144576 into slot 6. Value: 464855.
391865631: Producer 139708417144576entered critical section.
391872901: Item created by 139708417144576 into slot 6. Value: 464855.
391874995: Producer 139708417144576left critical section.
391880352: Producer 139708450715392entered critical section.
391880352: Producer 139708450715392entered critical section.
391888990: Item created by 139708450715392 into slot 7. Value: 50160.
391880352: Producer 139708450715392entered critical section.
391888990: Item created by 139708450715392 into slot 7. Value: 50160.
391891063: Producer 139708450715392left critical section.
391896778: Producer 139708459108096entered critical section.
391896778: Producer 139708459108096entered critical section.
391903950: Item created by 139708459108096 into slot 8. Value: 498178.
391896778: Producer 139708459108096entered critical section.
391903950: Item created by 139708459108096 into slot 8. Value: 498178.
391906072: Producer 139708459108096left critical section.
391911508: Producer 139708467500800entered critical section.
391911508: Producer 139708467500800entered critical section.
391920487: Item created by 139708467500800 into slot 9. Value: 917334.
391911508: Producer 139708467500800entered critical section.
391920487: Item created by 139708467500800 into slot 9. Value: 917334.
391922544: Producer 139708467500800left critical section.
391637865: Consumer 139708350002944entered critical section.
391637865: Consumer 139708350002944entered critical section.
391930791: Item removed by 139708350002944 from slot 0. Value: 994902.
391637865: Consumer 139708350002944entered critical section.
391930791: Item removed by 139708350002944 from slot 0. Value: 994902.
391933158: Consumer 139708350002944left critical section.
391967700: Consumer 139708358395648entered critical section.
391967700: Consumer 139708358395648entered critical section.
391976740: Item removed by 139708358395648 from slot 1. Value: 452289.
391967700: Consumer 139708358395648entered critical section.
391976740: Item removed by 139708358395648 from slot 1. Value: 452289.
391978960: Consumer 139708358395648left critical section.
391984926: Consumer 139708341610240entered critical section.
391984926: Consumer 139708341610240entered critical section.
391994663: Item removed by 139708341610240 from slot 2. Value: 775797.
391984926: Consumer 139708341610240entered critical section.
391994663: Item removed by 139708341610240 from slot 2. Value: 775797.
391996774: Consumer 139708341610240left critical section.
392002719: Consumer 139708366788352entered critical section.
392002719: Consumer 139708366788352entered critical section.
392009664: Item removed by 139708366788352 from slot 3. Value: 40803.
392002719: Consumer 139708366788352entered critical section.
392009664: Item removed by 139708366788352 from slot 3. Value: 40803.
392011765: Consumer 139708366788352left critical section.
392017278: Consumer 139708375181056entered critical section.
392017278: Consumer 139708375181056entered critical section.
392026094: Item removed by 139708375181056 from slot 4. Value: 859933.
392017278: Consumer 139708375181056entered critical section.
392026094: Item removed by 139708375181056 from slot 4. Value: 859933.
392028216: Consumer 139708375181056left critical section.
392034061: Consumer 139708383573760entered critical section.
392034061: Consumer 139708383573760entered critical section.
392036228: Item removed by 139708383573760 from slot 5. Value: 862962.
392034061: Consumer 139708383573760entered critical section.
392036228: Item removed by 139708383573760 from slot 5. Value: 862962.
392041046: Consumer 139708383573760left critical section.
392046521: Consumer 139708408751872entered critical section.
392046521: Consumer 139708408751872entered critical section.
392048239: Item removed by 139708408751872 from slot 6. Value: 464855.
392046521: Consumer 139708408751872entered critical section.
392048239: Item removed by 139708408751872 from slot 6. Value: 464855.
392050158: Consumer 139708408751872left critical section.
392054579: Consumer 139708400359168entered critical section.
392054579: Consumer 139708400359168entered critical section.
392056109: Item removed by 139708400359168 from slot 7. Value: 50160.
392054579: Consumer 139708400359168entered critical section.
392056109: Item removed by 139708400359168 from slot 7. Value: 50160.
392058047: Consumer 139708400359168left critical section.
392062556: Consumer 139708391966464entered critical section.
392062556: Consumer 139708391966464entered critical section.
392064062: Item removed by 139708391966464 from slot 8. Value: 498178.
392062556: Consumer 139708391966464entered critical section.
392064062: Item removed by 139708391966464 from slot 8. Value: 498178.
392065952: Consumer 139708391966464left critical section.
392070444: Consumer 139708333217536entered critical section.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392073850: Consumer 139708333217536left critical section.
392017278: Consumer 139708375181056entered critical section.
392026094: Item removed by 139708375181056 from slot 4. Value: 859933.
392028216: Consumer 139708375181056left critical section.
537760776: Consumer 139708375181056entered critical section.
392017278: Consumer 139708375181056entered critical section.
392026094: Item removed by 139708375181056 from slot 4. Value: 859933.
392028216: Consumer 139708375181056left critical section.
537760776: Consumer 139708375181056entered critical section.
537779758: Consumer 139708375181056 encountered empty buffer.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392073850: Consumer 139708333217536left critical section.
818759131: Consumer 139708333217536entered critical section.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392073850: Consumer 139708333217536left critical section.
818759131: Consumer 139708333217536entered critical section.
818777830: Consumer 139708333217536 encountered empty buffer.
391832787: Producer 139708442322688entered critical section.
391839933: Item created by 139708442322688 into slot 4. Value: 859933.
391842089: Producer 139708442322688left critical section.
104776263: Producer 139708442322688entered critical section.
391832787: Producer 139708442322688entered critical section.
391839933: Item created by 139708442322688 into slot 4. Value: 859933.
391842089: Producer 139708442322688left critical section.
104776263: Producer 139708442322688entered critical section.
104794865: Item created by 139708442322688 into slot 10. Value: 729187.
391832787: Producer 139708442322688entered critical section.
391839933: Item created by 139708442322688 into slot 4. Value: 859933.
391842089: Producer 139708442322688left critical section.
104776263: Producer 139708442322688entered critical section.
104794865: Item created by 139708442322688 into slot 10. Value: 729187.
104804537: Producer 139708442322688left critical section.
392017278: Consumer 139708375181056entered critical section.
392026094: Item removed by 139708375181056 from slot 4. Value: 859933.
392028216: Consumer 139708375181056left critical section.
537760776: Consumer 139708375181056entered critical section.
537779758: Consumer 139708375181056 encountered empty buffer.
104823321: Item removed by 139708375181056 from slot 10. Value: 729187.
392017278: Consumer 139708375181056entered critical section.
392026094: Item removed by 139708375181056 from slot 4. Value: 859933.
392028216: Consumer 139708375181056left critical section.
537760776: Consumer 139708375181056entered critical section.
537779758: Consumer 139708375181056 encountered empty buffer.
104823321: Item removed by 139708375181056 from slot 10. Value: 729187.
104838395: Consumer 139708375181056left critical section.
392054579: Consumer 139708400359168entered critical section.
392056109: Item removed by 139708400359168 from slot 7. Value: 50160.
392058047: Consumer 139708400359168left critical section.
305774914: Consumer 139708400359168entered critical section.
392054579: Consumer 139708400359168entered critical section.
392056109: Item removed by 139708400359168 from slot 7. Value: 50160.
392058047: Consumer 139708400359168left critical section.
305774914: Consumer 139708400359168entered critical section.
305793885: Consumer 139708400359168 encountered empty buffer.
392002719: Consumer 139708366788352entered critical section.
392009664: Item removed by 139708366788352 from slot 3. Value: 40803.
392011765: Consumer 139708366788352left critical section.
380742045: Consumer 139708366788352entered critical section.
392002719: Consumer 139708366788352entered critical section.
392009664: Item removed by 139708366788352 from slot 3. Value: 40803.
392011765: Consumer 139708366788352left critical section.
380742045: Consumer 139708366788352entered critical section.
380755715: Consumer 139708366788352 encountered empty buffer.
391865631: Producer 139708417144576entered critical section.
391872901: Item created by 139708417144576 into slot 6. Value: 464855.
391874995: Producer 139708417144576left critical section.
530764064: Producer 139708417144576entered critical section.
391865631: Producer 139708417144576entered critical section.
391872901: Item created by 139708417144576 into slot 6. Value: 464855.
391874995: Producer 139708417144576left critical section.
530764064: Producer 139708417144576entered critical section.
530783146: Item created by 139708417144576 into slot 11. Value: 697827.
391865631: Producer 139708417144576entered critical section.
391872901: Item created by 139708417144576 into slot 6. Value: 464855.
391874995: Producer 139708417144576left critical section.
530764064: Producer 139708417144576entered critical section.
530783146: Item created by 139708417144576 into slot 11. Value: 697827.
530838023: Producer 139708417144576left critical section.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392073850: Consumer 139708333217536left critical section.
818759131: Consumer 139708333217536entered critical section.
818777830: Consumer 139708333217536 encountered empty buffer.
530848657: Item removed by 139708333217536 from slot 11. Value: 697827.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392073850: Consumer 139708333217536left critical section.
818759131: Consumer 139708333217536entered critical section.
818777830: Consumer 139708333217536 encountered empty buffer.
530848657: Item removed by 139708333217536 from slot 11. Value: 697827.
530861640: Consumer 139708333217536left critical section.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392073850: Consumer 139708333217536left critical section.
818759131: Consumer 139708333217536entered critical section.
818777830: Consumer 139708333217536 encountered empty buffer.
530848657: Item removed by 139708333217536 from slot 11. Value: 697827.
530861640: Consumer 139708333217536left critical section.
931760566: Consumer 139708333217536entered critical section.
392070444: Consumer 139708333217536entered critical section.
392071917: Item removed by 139708333217536 from slot 9. Value: 917334.
392073850: Consumer 139708333217536left critical section.
818759131: Consumer 139708333217536entered critical section.
818777830: Consumer 139708333217536 encountered empty buffer.
530848657: Item removed by 139708333217536 from slot 11. Value: 697827.
530861640: Consumer 139708333217536left critical section.
931760566: Consumer 139708333217536entered critical section.
931779060: Consumer 139708333217536 encountered empty buffer.
391766506: Producer 139708475893504entered critical section.
391788442: Item created by 139708475893504 into slot 1. Value: 452289.
391790768: Producer 139708475893504left critical section.
965818384: Producer 139708475893504entered critical section.
391766506: Producer 139708475893504entered critical section.
391788442: Item created by 139708475893504 into slot 1. Value: 452289.
391790768: Producer 139708475893504left critical section.
965818384: Producer 139708475893504entered critical section.
965837852: Item created by 139708475893504 into slot 12. Value: 690947.
391766506: Producer 139708475893504entered critical section.
391788442: Item created by 139708475893504 into slot 1. Value: 452289.
391790768: Producer 139708475893504left critical section.

По сути, проблема появляется всякий раз, когда я пишу в файл. Например, код, генерирующий первые пару строк файла журнала, будет выглядеть следующим образом:

pthread_mutex_lock(&condp_mutex); //sets mutual exclusion for the producer
clock_gettime(CLOCK_REALTIME,&pts);
loginfo<<pts.tv_nsec<<": Producer "<<pthread_self()<< "entered critical section.\n";
char* logstring= createString(loginfo.str());
fprintf(logFile, "%s", logstring);
free(logstring);

В этом случае loginfo — это поток, который впоследствии преобразуется в строку, которая затем помещается в файл журнала. Теоретически, этот код должен выполняться только один раз для каждой записи в критической секции (обозначенной блокировкой мьютекса), но он печатается в файл журнала несколько раз.