hcq/MaxScale
hcq/MaxScale
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge pull request #43 from skysql/log_manager_test

Browse Source 
Log manager tests and fixes
This commit is contained in:
Vilho Raatikka 2014-09-10 17:25:19 +03:00
commit 65ec5c54ad
6 changed files with 331 additions and 34 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

170
log_manager/log_manager.cc
View File

@ -45,6 +45,12 @@
extern char *program_invocation_name;
extern char *program_invocation_short_name;
#if defined(SS_DEBUG)
static int write_index;
static int block_start_index;
static int prevval;
static simple_mutex_t msg_mutex;
#endif
/**
* Variable holding the enabled logfiles information.
* Used from log users to check enabled logs prior calling
@ -113,7 +119,7 @@ typedef struct blockbuf_st {
skygw_chk_t bb_chk_top;
#endif
logfile_id_t bb_fileid;
bool bb_isfull; /**< closed for disk write */
blockbuf_state_t bb_state; /**State of the block buffer*/
simple_mutex_t bb_mutex; /**< bb_buf_used, bb_isfull */
int bb_refcount; /**< protected by list mutex. #of clients */
// int bb_blankcount; /**< # of blanks used btw strings */
@ -333,6 +339,10 @@ static bool logmanager_init_nomutex(
#if defined(SS_DEBUG)
lm->lm_chk_top = CHK_NUM_LOGMANAGER;
lm->lm_chk_tail = CHK_NUM_LOGMANAGER;
write_index = 0;
block_start_index = 0;
prevval = -1;
simple_mutex_init(&msg_mutex, "Message mutex");
#endif
lm->lm_clientmes = skygw_message_init();
lm->lm_logmes = skygw_message_init();
@ -652,27 +662,73 @@ static int logmanager_write_log(
/** Findout how much can be safely written with current block size */
if (timestamp_len-1+str_len > lf->lf_buf_size)
{
safe_str_len = lf->lf_buf_size;
}
{
safe_str_len = lf->lf_buf_size;
}
else
{
safe_str_len = timestamp_len-1+str_len;
}
{
safe_str_len = timestamp_len-1+str_len;
}
/**
* Seek write position and register to block buffer.
* Then print formatted string to write position.
*/
#if defined (SS_LOG_DEBUG)
{
char *copy,*tok;
int tokval;
simple_mutex_lock(&msg_mutex,true);
copy = strdup(str);
tok = strtok(copy,"|");
tok = strtok(NULL,"|");
if(strstr(str,"message|") && tok){
tokval = atoi(tok);
if(prevval > 0){
ss_dassert(tokval == (prevval + 1));
}
prevval = tokval;
}
free(copy);
simple_mutex_unlock(&msg_mutex);
}
#endif
wp = blockbuf_get_writepos(&bb,
id,
safe_str_len,
flush);
#if defined (SS_LOG_DEBUG)
{
sprintf(wp,"[msg:%d]",atomic_add(&write_index,1));
safe_str_len -= strlen(wp);
wp += strlen(wp);
}
#endif
/**
* Write timestamp with at most <timestamp_len> characters
* to wp.
* Returned timestamp_len doesn't include terminating null.
*/
timestamp_len = snprint_timestamp(wp, timestamp_len);
/**
* Write next string to overwrite terminating null character
* of the timestamp string.
@ -682,7 +738,7 @@ static int logmanager_write_log(
} else {
snprintf(wp+timestamp_len, safe_str_len-timestamp_len, "%s", str);
}
/** write to syslog */
if (lf->lf_write_syslog)
{
@ -753,7 +809,7 @@ static int logmanager_write_log(
wp_c[timestamp_len-1+str_len-1]='\n';
/** lock-free unregistration, includes flush if
* bb_isfull */
* bb_state == BB_FULL */
blockbuf_unregister(bb_c);
}
} /* if (spread_down) */
@ -784,7 +840,7 @@ static void blockbuf_unregister(
/**
* if this is the last client in a full buffer, send write request.
*/
if (atomic_add(&bb->bb_refcount, -1) == 1 && bb->bb_isfull) {
if (atomic_add(&bb->bb_refcount, -1) == 1 && bb->bb_state == BB_FULL) {
skygw_message_send(lf->lf_logmes);
}
ss_dassert(bb->bb_refcount >= 0);
@ -816,12 +872,12 @@ static char* blockbuf_get_writepos(
size_t str_len,
bool flush)
{
logfile_t* lf;
mlist_t* bb_list;
char* pos = NULL;
mlist_node_t* node;
blockbuf_t* bb;
ss_debug(bool succp;)
logfile_t* lf;
mlist_t* bb_list;
char* pos = NULL;
mlist_node_t* node;
blockbuf_t* bb;
ss_debug(bool succp;)
CHK_LOGMANAGER(lm);
@ -838,6 +894,7 @@ static char* blockbuf_get_writepos(
* At least block buffer exists on the list.
*/
node = bb_list->mlist_first;
/** Loop over blockbuf list to find write position */
while (true) {
@ -852,22 +909,25 @@ static char* blockbuf_get_writepos(
/** Lock buffer */
simple_mutex_lock(&bb->bb_mutex, true);
if (bb->bb_isfull || bb->bb_buf_left < str_len) {
if (bb->bb_state == BB_FULL || bb->bb_buf_left < str_len) {
/**
* This block buffer is too full.
* Send flush request to file writer thread. This causes
* flushing all buffers, and (eventually) frees buffer space.
*/
blockbuf_register(bb);
bb->bb_isfull = true;
blockbuf_unregister(bb);
blockbuf_register(bb);
bb->bb_state = BB_FULL;
blockbuf_unregister(bb);
/** Unlock buffer */
simple_mutex_unlock(&bb->bb_mutex);
/** Lock list */
simple_mutex_lock(&bb_list->mlist_mutex, true);
/** Unlock buffer */
simple_mutex_unlock(&bb->bb_mutex);
/** Lock list */
simple_mutex_lock(&bb_list->mlist_mutex, true);
/**
* If next node exists move forward. Else check if there is
* space for a new block buffer on the list.
@ -916,7 +976,28 @@ static char* blockbuf_get_writepos(
node = bb_list->mlist_first;
continue;
}
} else {
}else if(bb->bb_state == BB_CLEARED){
/**
*Move the full buffer to the end of the list
*/
simple_mutex_unlock(&bb->bb_mutex);
simple_mutex_lock(&bb_list->mlist_mutex, true);
if(node->mlnode_next){
bb_list->mlist_first = node->mlnode_next;
bb_list->mlist_last->mlnode_next = node;
node->mlnode_next = NULL;
bb_list->mlist_last = node;
node = bb_list->mlist_first;
}
bb->bb_state = BB_READY;
}else if (bb->bb_state == BB_READY){
/**
* There is space for new log string.
*/
@ -924,9 +1005,11 @@ static char* blockbuf_get_writepos(
}
} /** while (true) */
} else {
/**
* Create the first block buffer to logfile's blockbuf list.
*/
bb = blockbuf_init(id);
CHK_BLOCKBUF(bb);
@ -952,7 +1035,7 @@ static char* blockbuf_get_writepos(
} /* if (bb_list->mlist_nodecount > 0) */
ss_dassert(pos == NULL);
ss_dassert(!(bb->bb_isfull || bb->bb_buf_left < str_len));
ss_dassert(!(bb->bb_state == BB_FULL || bb->bb_buf_left < str_len));
ss_dassert(bb_list->mlist_nodecount <= bb_list->mlist_nodecount_max);
/**
@ -991,7 +1074,7 @@ static char* blockbuf_get_writepos(
* If flush flag is set, set buffer full. As a consequence, no-one
* can write to it before it is flushed to disk.
*/
bb->bb_isfull = (flush == true ? true : bb->bb_isfull);
bb->bb_state = (flush == true ? BB_FULL : bb->bb_state);
/** Unlock buffer */
simple_mutex_unlock(&bb->bb_mutex);
@ -1021,6 +1104,12 @@ static blockbuf_t* blockbuf_init(
bb->bb_buf_left = MAX_LOGSTRLEN;
bb->bb_buf_size = MAX_LOGSTRLEN;
#if defined(SS_LOG_DEBUG)
sprintf(bb->bb_buf,"[block:%d]",atomic_add(&block_start_index,1));
bb->bb_buf_used += strlen(bb->bb_buf);
bb->bb_buf_left -= strlen(bb->bb_buf);
#endif
CHK_BLOCKBUF(bb);
return bb;
}
@ -1170,6 +1259,9 @@ int skygw_log_write_flush(
/**
* Find out the length of log string (to be formatted str).
*/
va_start(valist, str);
len = vsnprintf(NULL, 0, str, valist);
va_end(valist);
@ -1220,6 +1312,9 @@ int skygw_log_write(
err = 1;
goto return_unregister;
}
/**
* Find out the length of log string (to be formatted str).
*/
@ -1233,6 +1328,7 @@ int skygw_log_write(
/**
* Write log string to buffer and add to file write list.
*/
va_start(valist, str);
err = logmanager_write_log(id, false, true, true, len, str, valist);
va_end(valist);
@ -2257,7 +2353,7 @@ static void filewriter_done(
* lists of each logfile object.
*
* Block buffer is written to log file if
* 1. bb_isfull == true,
* 1. bb_state == true,
* 2. logfile object's lf_flushflag == true, or
* 3. skygw_thread_must_exit returns true.
*
@ -2297,7 +2393,7 @@ static void* thr_filewriter_fun(
blockbuf_t* bb;
mlist_node_t* node;
int i;
bool flush_blockbuf; /**< flush single block buffer. */
blockbuf_state_t flush_blockbuf; /**< flush single block buffer. */
bool flush_logfile; /**< flush logfile */
bool flushall_logfiles;/**< flush all logfiles */
size_t vn1;
@ -2356,10 +2452,10 @@ static void* thr_filewriter_fun(
/** Lock block buffer */
simple_mutex_lock(&bb->bb_mutex, true);
flush_blockbuf = bb->bb_isfull;
flush_blockbuf = bb->bb_state;
if (bb->bb_buf_used != 0 &&
(flush_blockbuf ||
(flush_blockbuf == BB_FULL ||
flush_logfile ||
flushall_logfiles))
{
@ -2374,7 +2470,7 @@ static void* thr_filewriter_fun(
&bb->bb_mutex,
true);
}
skygw_file_write(file,
(void *)bb->bb_buf,
bb->bb_buf_used,
@ -2387,7 +2483,13 @@ static void* thr_filewriter_fun(
bb->bb_buf_left = bb->bb_buf_size;
bb->bb_buf_used = 0;
memset(bb->bb_buf, 0, bb->bb_buf_size);
bb->bb_isfull = false;
bb->bb_state = BB_CLEARED;
#if defined(SS_LOG_DEBUG)
sprintf(bb->bb_buf,"[block:%d]",atomic_add(&block_start_index,1));
bb->bb_buf_used += strlen(bb->bb_buf);
bb->bb_buf_left -= strlen(bb->bb_buf);
#endif
}
/** Release lock to block buffer */
simple_mutex_unlock(&bb->bb_mutex);

6
log_manager/log_manager.h
View File

@ -22,6 +22,12 @@ typedef struct logfile_st logfile_t;
typedef struct fnames_conf_st fnames_conf_t;
typedef struct logmanager_st logmanager_t;
typedef enum {
BB_READY = 0x00,
BB_FULL,
BB_CLEARED
} blockbuf_state_t;
typedef enum {
LOGFILE_ERROR = 1,
LOGFILE_FIRST = LOGFILE_ERROR,

5
log_manager/makefile
View File

@ -8,6 +8,11 @@ SRCS := log_manager.cc
UTILS_PATH := $(ROOT_PATH)/utils
CUR_DIR := $(shell pwd)
ifeq ($(ADD_DEBUG_TAGS),Y)
CFLAGS += -DSS_LOG_DEBUG
endif
makeall: clean all
clean:

61
log_manager/test/logorder.sh Executable file
View File

@ -0,0 +1,61 @@
#! /bin/bash
if [[ $# -lt 4 ]]
then
echo "Usage: logorder.sh <iterations> <frequency of flushes> <message size>"
echo "To disable log flushing, use 0 for flush frequency"
exit
fi
rm *.log
#Create large messages
$PWD/testorder $1 $2 $3
TESTLOG=$4
MCOUNT=$1
BLOCKS=`cat skygw_err1.log |tr -s ' '|grep -o 'block:[[:digit:]]\+'|cut -d ':' -f 2`
MESSAGES=`cat skygw_err1.log |tr -s ' '|grep -o 'message|[[:digit:]]\+'|cut -d '|' -f 2`
prev=0
error=0
for i in $BLOCKS
do
if [[ $i -le $prev ]]
then
error=1
echo "block mismatch: $i was after $prev." >> $TESTLOG
fi
prev=$i
done
if [[ error -eq 0 ]]
then
echo "Block buffers were in order" >> $TESTLOG
else
echo "Error: block buffers were written in the wrong order" >> $TESTLOG
fi
prev=0
error=0
for i in $MESSAGES
do
if [[ $i -ne $(( prev + 1 )) ]]
then
error=1
echo "message mismatch: $i was after $prev." >> $TESTLOG
fi
prev=$i
done
if [[ error -eq 0 ]]
then
echo "Block buffer messages were in order" >> $TESTLOG
else
echo "Error: block buffer messages were written in the wrong order" >> $TESTLOG
fi

18
log_manager/test/makefile
View File

@ -28,10 +28,13 @@ testall:
cleantests:
- $(DEL) *.o
- $(DEL) *.log
- $(DEL) testlog
- $(DEL) testorder
- $(DEL) *~
buildtests:
$(MAKE) -C $(LOG_MANAGER_PATH) ADD_DEBUG_TAGS=Y
$(CC) $(CFLAGS) \
-L$(LOG_MANAGER_PATH) \
-Wl,-rpath,$(DEST)/lib \
@ -41,6 +44,17 @@ buildtests:
-I$(LOG_MANAGER_PATH) -I$(UTILS_PATH) testlog.c \
-lstdc++ -llog_manager $(LDLIBS) \
$(UTILS_PATH)/skygw_utils.o
$(CC) $(CFLAGS) \
-L$(LOG_MANAGER_PATH) \
-Wl,-rpath,$(DEST)/lib \
-Wl,-rpath,$(LOG_MANAGER_PATH)/ \
-o testorder \
-I$(MARIADB_SRC_PATH)/include \
-I$(LOG_MANAGER_PATH) -I$(UTILS_PATH) testorder.c \
-lstdc++ -llog_manager $(LDLIBS) \
$(UTILS_PATH)/skygw_utils.o
runtests:
@ -61,6 +75,10 @@ runtests:
@echo "Use 16 threads" >> $(TESTLOG)
@echo "" >> $(TESTLOG)
@-$(LAUNCH_DEBUGGER) $(TESTAPP) "-t 16" 2>>$(TESTLOG)
@echo "" >> $(TEST_MAXSCALE_LOG)
@echo "Test Message Order" >> $(TEST_MAXSCALE_LOG)
@echo "" >> $(TEST_MAXSCALE_LOG)
./logorder.sh 500 0 500 $(TEST_MAXSCALE_LOG)
@echo "Log Manager PASSED" >> $(TESTLOG)
@echo "" >> $(TESTLOG)

105
log_manager/test/testorder.c Normal file
View File

@ -0,0 +1,105 @@
/*
* This file is distributed as part of the SkySQL Gateway. It is free
* software: you can redistribute it and/or modify it under the terms of the
* GNU General Public License as published by the Free Software Foundation,
* version 2.
*
* This program is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
* FOR A PARTICULAR PURPOSE. See the GNU General Public License for more
* details.
*
* You should have received a copy of the GNU General Public License along with
* this program; if not, write to the Free Software Foundation, Inc., 51
* Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Copyright SkySQL Ab 2013
*/
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <skygw_utils.h>
#include <log_manager.h>
int main(int argc, char** argv)
{
int iterations = 0, i, interval = 10;
int block_size;
int succp = 0, err = 0;
char cwd[1024];
char tmp[2048];
char *message;
char** optstr;
long msg_index = 1;
memset(cwd,0,1024);
if( argc <4){
fprintf(stderr,
"Log Manager Log Order Test\n"
"Writes an ascending number into the error log to determine if log writes are in order.\n"
"Usage:\t testorder <iterations> <frequency of log flushes> <size of message in bytes>\n");
return 1;
}
block_size = atoi(argv[3]);
if(block_size < 1){
fprintf(stderr,"Message size too small, must be at least 1 byte long.");
}
if(getcwd(cwd,sizeof(cwd)) == NULL ||
(optstr = (char**)malloc(sizeof(char*)*4)) == NULL ||
(message = (char*)malloc(sizeof(char)*block_size))== NULL){
fprintf(stderr,"Fatal Error, exiting...");
return 1;
}
memset(tmp,0,1024);
sprintf(tmp,"%s",cwd);
optstr[0] = strdup("log_manager");
optstr[1] = strdup("-j");
optstr[2] = strdup(tmp);
optstr[3] = NULL;
iterations = atoi(argv[1]);
interval = atoi(argv[2]);
succp = skygw_logmanager_init( 3, optstr);
ss_dassert(succp);
skygw_log_disable(LOGFILE_TRACE);
skygw_log_disable(LOGFILE_MESSAGE);
skygw_log_disable(LOGFILE_DEBUG);
for(i = 0;i<iterations;i++){
sprintf(message,"message|%ld",msg_index++);
memset(message + strlen(message),' ',block_size - strlen(message));
memset(message + block_size - 1,'\0',1);
if(interval > 0 && i % interval == 0){
err = skygw_log_write_flush(LOGFILE_ERROR, message);
}else{
err = skygw_log_write(LOGFILE_ERROR, message);
}
if(err){
fprintf(stderr,"Error: log_manager returned %d",err);
break;
}
usleep(100);
//printf("%s\n",message);
}
skygw_log_flush(LOGFILE_ERROR);
skygw_logmanager_done();
free(message);
free(optstr[0]);
free(optstr[1]);
free(optstr[2]);
free(optstr[3]);
free(optstr);
return 0;
}