1. implement decoupling log full (UNIV_LIBOBJ_WAL_ELR, 2. skip log_write_up_to() in logcheckpoint(), and flush log buffer when its size reach 50% capacity

Author: trdtnguyen

build_mysql.sh

@@ -15,9 +15,10 @@ IS_DEBUG=0
 ### PB-NVM + PL-NVM
 #BUILD_NAME="-DUNIV_PMEMOBJ_PART_PL_STAT -DUNIV_PMEMOBJ_PAGE_LOG -DUNIV_PMEMOBJ_PART_PL -DUNIV_PMEMOBJ_PL -DUNIV_OPENMP -DUNIV_PMEMOBJ_BLOOM -DUNIV_PMEMOBJ_BUF -DUNIV_PMEMOBJ_BUF_PARTITION -DUNIV_PMEMOBJ_BUF_FLUSHER -DUNIV_PMEMOBJ_BUF_RECOVERY -DUNIV_PMEMOBJ_BUF_STAT -DUNIV_TRACE_FLUSH_TIME"
 
-BUILD_NAME="-DUNIV_TRACE_FLUSH_TIME"
+#BUILD_NAME="-DUNIV_TRACE_FLUSH_TIME"
 #BUILD_NAME="-DUNIV_TRACE_FLUSH_TIME -DUNIV_SKIPLOG"
 #BUILD_NAME="-DUNIV_PMEMOBJ_WAL -DUNIV_TRACE_FLUSH_TIME"
+BUILD_NAME="-DUNIV_PMEMOBJ_WAL -DUNIV_PMEMOBJ_WAL_ELR -DUNIV_TRACE_FLUSH_TIME"
 #BUILD_NAME="-DUNIV_PMEMOBJ_PPL_STAT -DUNIV_PMEMOBJ_PAGE_LOG -DUNIV_PMEMOBJ_PART_PL -DUNIV_PMEMOBJ_PL -DUNIV_TRACE_FLUSH_TIME"
 
 

storage/innobase/log/log0log.cc

@@ -421,8 +421,13 @@ log_reserve_and_open(
 
 	len_upper_limit = LOG_BUF_WRITE_MARGIN + srv_log_write_ahead_size
 			  + (5 * len) / 4;
-
+#if defined (UNIV_PMEMOBJ_WAL)
+	//in PMEMOBJ_WAL, because we do not flush log at commit, we shouldn't keep the log buffer
+	//too large, we flush when its size is x% (25, 50, 75) capacity
+	if (log_sys->buf_free + len_upper_limit > log_sys->buf_size / 2) {
+#else //original
 	if (log_sys->buf_free + len_upper_limit > log_sys->buf_size) {
+#endif
 		log_mutex_exit();
 
 		DEBUG_SYNC_C("log_buf_size_exceeded");
@@ -438,7 +443,6 @@ log_reserve_and_open(
 		log_mutex_enter();
 		goto loop;
 	}
-
 	return(log_sys->lsn);
 }
 
@@ -478,11 +482,15 @@ log_write_low(
 
 #if defined (UNIV_PMEMOBJ_LOG) || defined (UNIV_PMEMOBJ_WAL)
 	//copy the trasaction's log records to persistent memory
+	//The mfence per copy version
 TX_BEGIN(gb_pmw->pop) {
 	TX_MEMCPY(log->buf + log->buf_free, str, len);
 } TX_ONABORT {
 } TX_END
-	//pmemobj_memcpy_persist(gb_pmw->pop, log->buf + log->buf_free, str, len);
+	
+	//The unsafe version
+	//ut_memcpy(log->buf + log->buf_free, str, len);
+
 	//set the flag here
 	gb_pmw->plogbuf->need_recv = true;
 #else //original
@@ -2007,9 +2015,11 @@ log_checkpoint(
 	}
 
 	log_mutex_exit();
-
+#if defined (UNIV_PMEMOBJ_WAL)
+	//do nothing
+#else //original
 	log_write_up_to(flush_lsn, true);
-
+#endif
 	DBUG_EXECUTE_IF(
 		"using_wa_checkpoint_middle",
 		if (write_always) {

storage/innobase/mtr/mtr0mtr.cc

@@ -41,9 +41,10 @@ Created 11/26/1995 Heikki Tuuri
 
 #if defined (UNIV_TRACE_FLUSH_TIME)
 extern volatile int64 gb_write_log_time;
+extern volatile int64 gb_n_write_log;
 #endif
 
-#if defined (UNIV_PMEMOBJ_PART_PL)
+#if defined (UNIV_PMEMOBJ_PART_PL) || defined (UNIV_PMEMOBJ_WAL_ELR)
 #include "my_pmemobj.h"
 extern PMEM_WRAPPER* gb_pmw; 
 #endif /* UNIV_PMEMOBJ_PART_PL */
@@ -1109,6 +1110,7 @@ mtr_t::Command::execute()
 	ulint exec_time = end_time - start_time;
 	//my_atomic_add64(&gb_write_log_time, exec_time);
 	__sync_fetch_and_add(&gb_write_log_time, exec_time);
+	__sync_fetch_and_add(&gb_n_write_log, 1);
 #endif
 }
 #else //old method
@@ -1152,6 +1154,232 @@ mtr_t::Command::execute()
 	release_resources();
 }
 #endif //UNIV_PMEMOBJ_PART_PL
+#elif defined (UNIV_PMEMOBJ_WAL) && defined (UNIV_PMEMOBJ_WAL_ELR)
+	//Early lock release
+void
+mtr_t::Command::execute()
+{
+	ulint len;
+	ulint str_len;
+	ulint len_tem;
+	ulint data_len;
+	ulint n_recs;
+
+	byte* start_cpy;
+	ulint len_cpy;
+
+	log_t*	log	= log_sys;
+	byte*	log_block;
+
+	fil_space_t*	space;
+
+	const mtr_buf_t::block_t*	front = m_impl->m_log.front();
+	byte* start_log_ptr = (byte*) front->begin(); 	
+	byte* str = start_log_ptr;
+
+	ut_ad(m_impl->m_log_mode != MTR_LOG_NONE);
+
+	////Simulate prepare_write()
+	switch (m_impl->m_log_mode) {
+	case MTR_LOG_SHORT_INSERTS:
+		ut_ad(0);
+		/* fall through (write no redo log) */
+	case MTR_LOG_NO_REDO:
+	case MTR_LOG_NONE:
+		ut_ad(m_impl->m_log.size() == 0);
+		log_mutex_enter();
+		m_end_lsn = m_start_lsn = log_sys->lsn;
+		//return(0);
+		len = 0;
+		break;
+	case MTR_LOG_ALL:
+		break;
+	}
+	
+	if (m_impl->m_log_mode == MTR_LOG_ALL) {
+
+		len	= m_impl->m_log.size();
+		n_recs	= m_impl->m_n_log_recs;
+		ut_ad(len > 0);
+		ut_ad(n_recs > 0);
+
+		if (len > log_sys->buf_size / 2) {
+			log_buffer_extend((len + 1) * 2);
+		}
+
+		ut_ad(m_impl->m_n_log_recs == n_recs);
+
+		space = m_impl->m_user_space;
+
+		if (space != NULL && is_system_or_undo_tablespace(space->id)) {
+			/* Omit MLOG_FILE_NAME for predefined tablespaces. */
+			space = NULL;
+		}
+
+		log_mutex_enter();
+
+		if (fil_names_write_if_was_clean(space, m_impl->m_mtr)) {
+			/* This mini-transaction was the first one to modify
+			   this tablespace since the latest checkpoint, so
+			   some MLOG_FILE_NAME records were appended to m_log. */
+			ut_ad(m_impl->m_n_log_recs > n_recs);
+			mlog_catenate_ulint(
+					&m_impl->m_log, MLOG_MULTI_REC_END, MLOG_1BYTE);
+			len = m_impl->m_log.size();
+		} else {
+			/* This was not the first time of dirtying a
+			   tablespace since the latest checkpoint. */
+
+			ut_ad(n_recs == m_impl->m_n_log_recs);
+
+			if (n_recs <= 1) {
+				ut_ad(n_recs == 1);
+
+				/* Flag the single log record as the
+				   only record in this mini-transaction. */
+				*m_impl->m_log.front()->begin()
+					|= MLOG_SINGLE_REC_FLAG;
+			} else {
+				/* Because this mini-transaction comprises
+				   multiple log records, append MLOG_MULTI_REC_END
+				   at the end. */
+
+				mlog_catenate_ulint(
+						&m_impl->m_log, MLOG_MULTI_REC_END,
+						MLOG_1BYTE);
+				len++;
+			}
+		}
+
+		/* check and attempt a checkpoint if exceeding capacity */
+		log_margin_checkpoint_age(len);
+	} // end if (m_impl->m_log_mode == MTR_LOG_ALL)
+
+	////End simulate prepare_write()
+	
+	if (len > 0){
+		//simulate finish_write()	
+		ut_ad(m_impl->m_log_mode == MTR_LOG_ALL);
+		ut_ad(log_mutex_own());
+		ut_ad(m_impl->m_log.size() == len);
+		ut_ad(len > 0);
+
+		if (m_impl->m_log.is_small()) {
+			const mtr_buf_t::block_t*	front = m_impl->m_log.front();
+			ut_ad(len <= front->used());
+
+			m_end_lsn = log_reserve_and_write_fast(
+					front->begin(), len, &m_start_lsn);
+
+			if (m_end_lsn > 0) {
+				goto skip_write;
+			}
+		}
+		/* Open the database log for log_write_low
+		 * This function also check for flush log buffer if lsn + len > log buffer capacity
+		 * 
+		 * */
+		m_start_lsn = log_reserve_and_open(len);
+
+		//simulate log_write_low(), we do the same as log_write_low() except skip memcpy()
+
+		//assign as parameter pass
+		str_len = len;	
+		str = start_log_ptr;
+
+part_loop:
+		data_len = (log->buf_free % OS_FILE_LOG_BLOCK_SIZE) + str_len;
+		if (data_len <= OS_FILE_LOG_BLOCK_SIZE - LOG_BLOCK_TRL_SIZE) {
+
+			/* The string fits within the current log block */
+
+			len_tem = str_len;
+		} else {
+			data_len = OS_FILE_LOG_BLOCK_SIZE - LOG_BLOCK_TRL_SIZE;
+
+			len_tem = OS_FILE_LOG_BLOCK_SIZE
+				- (log->buf_free % OS_FILE_LOG_BLOCK_SIZE)
+				- LOG_BLOCK_TRL_SIZE;
+		}
+
+		//save the pointer and the len to be copied later
+		start_cpy = log->buf + log->buf_free;
+		len_cpy = len_tem;
+
+		str_len -= len_tem;
+		str = str + len_tem;
+
+		log_block = static_cast<byte*>(
+				ut_align_down(
+					log->buf + log->buf_free, OS_FILE_LOG_BLOCK_SIZE));
+
+		log_block_set_data_len(log_block, data_len);
+
+		if (data_len == OS_FILE_LOG_BLOCK_SIZE - LOG_BLOCK_TRL_SIZE) {
+			/* This block became full */
+			log_block_set_data_len(log_block, OS_FILE_LOG_BLOCK_SIZE);
+			log_block_set_checkpoint_no(log_block,
+					log_sys->next_checkpoint_no);
+			len_tem += LOG_BLOCK_HDR_SIZE + LOG_BLOCK_TRL_SIZE;
+
+			log->lsn += len_tem;
+
+			/* Initialize the next block header */
+			log_block_init(log_block + OS_FILE_LOG_BLOCK_SIZE, log->lsn);
+		} else {
+			log->lsn += len_tem;
+		}
+
+		log->buf_free += len_tem;
+
+		ut_ad(log->buf_free <= log->buf_size);
+
+		if (str_len > 0) {
+			goto part_loop;
+		}
+#if defined(UNIV_PMEMOBJ_LOG) || defined(UNIV_PMEMOBJ_WAL)
+		// update the lsn and buf_free
+		gb_pmw->plogbuf->lsn = log->lsn;
+		gb_pmw->plogbuf->buf_free = log->buf_free;	
+#endif /*UNIV_PMEMOBJ_LOG */
+		srv_stats.log_write_requests.inc();
+
+		//end simulate log_write_low() ///
+
+		m_end_lsn = log_close();
+
+	} //end if len > 0
+skip_write:
+		//////  end simulate finish_write() ////////////
+
+	if (m_impl->m_made_dirty) {
+		log_flush_order_mutex_enter();
+	}
+
+	/* It is now safe to release the log mutex because the
+	flush_order mutex will ensure that we are the first one
+	to insert into the flush list. */
+	log_mutex_exit();
+
+	//now we do the memcpy
+	TX_BEGIN(gb_pmw->pop) {
+		TX_MEMCPY(start_cpy, start_log_ptr, len_cpy);
+	} TX_ONABORT {
+	} TX_END
+	gb_pmw->plogbuf->need_recv = true;
+
+	m_impl->m_mtr->m_commit_lsn = m_end_lsn;
+
+	release_blocks();
+
+	if (m_impl->m_made_dirty) {
+		log_flush_order_mutex_exit();
+	}
+
+	release_latches();
+
+	release_resources();
+}
 #else //original
 void
 mtr_t::Command::execute()
@@ -1191,6 +1419,7 @@ mtr_t::Command::execute()
 	ulint exec_time = end_time - start_time;
 	//my_atomic_add64(&gb_write_log_time, exec_time);
 	__sync_fetch_and_add(&gb_write_log_time, exec_time);
+	__sync_fetch_and_add(&gb_n_write_log, 1);
 #endif
 }
 #endif // UNIV_PMEMOBJ_PL

storage/innobase/pmem/pmem0log.cc

@@ -2844,12 +2844,12 @@ __print_lock_overhead(FILE* f,
 	avg_log_write_lock_wait_time = avg_log_write_lock_wait_time / n;
 	avg_log_flush_lock_wait_time = avg_log_flush_lock_wait_time / n;
 
-	fprintf(f, "max_log_write_wait(us) max_log_flush_wait(us) avg_log_write_wait avg_log_flush_wait \t %zu \t %f \t %zu \t %f\n", 
+	fprintf(f, "max_log_write_wait(us) avg_log_write_wait(us) max_log_flush_wait(us) avg_log_flush_wait \t %zu \t %f \t %zu \t %f\n", 
 			max_log_write_lock_wait_time,
 			avg_log_write_lock_wait_time,
 			max_log_flush_lock_wait_time,
 			avg_log_flush_lock_wait_time);
-	printf("max_log_write_wait(us) max_log_flush_wait(us) avg_log_write_wait avg_log_flush_wait \t %zu \t %f \t %zu \t %f\n", 
+	printf("max_log_write_wait(us) avg_log_write_wait(us) max_log_flush_wait(us) avg_log_flush_wait \t %zu \t %f \t %zu \t %f\n", 
 			max_log_write_lock_wait_time,
 			avg_log_write_lock_wait_time,
 			max_log_flush_lock_wait_time,

storage/innobase/srv/srv0start.cc

@@ -176,7 +176,9 @@ static pfs_os_file_t	files[1000];
 #if defined (UNIV_TRACE_FLUSH_TIME)
 ulint gb_flush_time = 0;
 volatile int64 gb_write_log_time = 0;
+volatile int64 gb_n_write_log = 0;
 volatile int64 gb_flush_log_time = 0;
+volatile int64 gb_n_flush_log = 0;
 FILE* gb_trace_file = fopen("trace_flush.txt","a");
 #endif 
 
@@ -2927,7 +2929,11 @@ innobase_shutdown_for_mysql(void)
 #endif
 
 #if defined (UNIV_TRACE_FLUSH_TIME)
-	printf("===>TRACE TIME: flush_time (ms) = %zu write_log (ms)%zu  flush_log (ms) %zu\n", gb_flush_time, gb_write_log_time/1000, gb_flush_log_time/1000);
+	printf("===>TRACE TIME: flush_time (ms) = %zu write_log (ms)%zu  avg_write_log (ms/write) %f flush_log (ms) %zu\n",
+		   	gb_flush_time,
+		   	gb_write_log_time/1000,
+			(gb_write_log_time * 1.0)/1000/gb_n_write_log,
+		   	gb_flush_log_time/1000);
 //Add the method name in the trace out
 #if defined (UNIV_PMEMOBJ_DBW)
 	fprintf(gb_trace_file, "\n===>TRACE_FLUSH_TIME_DBW: total flush time (ms) = %zu", gb_flush_time);
@@ -2942,9 +2948,17 @@ innobase_shutdown_for_mysql(void)
 #elif defined (UNIV_PMEMOBJ_WAL)
 	fprintf(gb_trace_file, "\n===>TRACE TIME WAL_NVM: flush_time (ms) = %zu write_log (ms)%zu  flush_log (ms) %zu", gb_flush_time, gb_write_log_time/1000, gb_flush_log_time/1000);
 #elif defined (UNIV_PMEMOBJ_PART_PL)
-	fprintf(gb_trace_file, "\n===>TRACE TIME PPL: flush_time (ms) = %zu write_log (ms)%zu  flush_log (ms) %zu", gb_flush_time, gb_write_log_time/1000, gb_flush_log_time/1000);
+	fprintf(gb_trace_file, "===>TRACE TIME_PPL: flush_time (ms) = %zu write_log (ms)%zu  avg_write_log (ms/write) %f flush_log (ms) %zu\n",
+		   	gb_flush_time,
+		   	gb_write_log_time/1000,
+			(gb_write_log_time * 1.0)/1000/gb_n_write_log,
+		   	gb_flush_log_time/1000);
 #else
-	fprintf(gb_trace_file, "\n===>TRACE TIME ORI: flush_time (ms) = %zu write_log (ms)%zu  flush_log (ms) %zu", gb_flush_time, gb_write_log_time/1000, gb_flush_log_time/1000);
+	fprintf(gb_trace_file, "===>TRACE TIME_ORI: flush_time (ms) = %zu write_log (ms)%zu  avg_write_log (ms/write) %f flush_log (ms) %zu\n",
+		   	gb_flush_time,
+		   	gb_write_log_time/1000,
+			(gb_write_log_time * 1.0)/1000/gb_n_write_log,
+		   	gb_flush_log_time/1000);
 #endif //defined (UNIV_PMEMOBJ_DBW)
 	fclose(gb_trace_file);
 #endif  //defined (UNIV_TRACE_FLUSH_TIME)