Log all filerep logs to server logs instead of separate log files.

In some cases, the filerep processes get stuck waiting for the spin locks on an
in memory log and the postmaster PANICs if they can't acquire a lock after
timeout period. In order to avoid locking related issues we want to avoid
acquiring the locks in the first place. This patch introduces a new guc which
will cause filerep logs to be logged to server logs and will avoid logging to
the in memory log.

src/backend/cdb/cdbfilerep.c

@@ -1319,6 +1319,10 @@ FileRep_CheckFlushLogs(
 					   volatile	FileRepLogShmem_s	*logShmem,
 					   bool							isConfigLog)
 {
+
+	if (log_filerep_to_syslogger)
+		return;
+
 	uint32	dataLength = 0;
 	bool	flushConfigLog = FALSE;
 	char	*configBegin = NULL;
@@ -1378,9 +1382,55 @@ FileRep_InsertLogEntry(
 
 	struct timeval	logTime;
 
-	if (Debug_filerep_print || (*fileRepAckShmemArray) == NULL)
+	if (!Debug_filerep_print || (*fileRepAckShmemArray) == NULL)
 		return;
 
+	if (log_filerep_to_syslogger)
+	{
+		ereport(LOG,
+		(errmsg("'%s', "
+			"filerep operation '%s', "
+			"relation type '%s', "
+			"'%d', '%d', "
+			"header crc '%u', "
+			"body crc '%u', "
+			"ack state '%s', "
+			"'%p', '%p', '%p', '%p', '%p', '%d', '%d', "
+			"'%p', '%p', '%p', '%p', '%p', '%d', '%d', "
+			"mirroring role '%s', mirroring state '%s', segment state '%s', filerep state, '%s'"
+			"process name(pid) '%s(%d)' ",
+			routineName,
+			FileRepOperationToString[fileRepOperation],
+			FileRepRelationTypeToString[fileRepRelationType],
+			localCount,
+			fileRepMessageCount,
+			fileRepMessageHeaderCrc,
+			fileRepMessageBodyCrc,
+			FileRepAckStateToString[fileRepAckState],
+			fileRepShmemArray[fileRepProcIndex]->positionBegin,
+			fileRepShmemArray[fileRepProcIndex]->positionEnd,
+			fileRepShmemArray[fileRepProcIndex]->positionInsert,
+			fileRepShmemArray[fileRepProcIndex]->positionConsume,
+			fileRepShmemArray[fileRepProcIndex]->positionWraparound,
+			fileRepShmemArray[fileRepProcIndex]->insertCount,
+			fileRepShmemArray[fileRepProcIndex]->consumeCount,
+			(*fileRepAckShmemArray)->positionBegin,
+			(*fileRepAckShmemArray)->positionEnd,
+			(*fileRepAckShmemArray)->positionInsert,
+			(*fileRepAckShmemArray)->positionConsume,
+			(*fileRepAckShmemArray)->positionWraparound,
+			(*fileRepAckShmemArray)->insertCount,
+			(*fileRepAckShmemArray)->consumeCount,
+			FileRepRoleToString[fileRepRole],
+			DataStateToString[dataState],
+			SegmentStateToString[segmentState],
+			FileRepStateToString[FileRepSubProcess_GetState()],
+			FileRepProcessTypeToString[fileRepProcessType],
+			getpid())));
+
+			return;
+	}
+
 	halfLength = (fileRepLogShmem->logEnd - fileRepLogShmem->logBegin) / 2;
 
 	gettimeofday(&logTime, NULL);
@@ -1606,11 +1656,14 @@ FileRepLog_ShmemReInit(void)
 static void
 FileRep_FlushLogActiveSlot(void)
 {
+	if (log_filerep_to_syslogger)
+		return;
+
 	uint32 dataLength = 0;
 
 	dataLength = (fileRepConfigLogShmem->logEnd - fileRepConfigLogShmem->logBegin) / 2;
 
-	if (! Debug_filerep_config_print)
+	if (Debug_filerep_config_print)
 	{
 		if (fileRepConfigLogShmem->activeSlot1 == TRUE)
 		{
@@ -1630,7 +1683,7 @@ FileRep_FlushLogActiveSlot(void)
 
 	dataLength = (fileRepLogShmem->logEnd - fileRepLogShmem->logBegin) / 2;
 
-	if (! Debug_filerep_print)
+	if (Debug_filerep_print)
 	{
 		if (fileRepLogShmem->activeSlot1 == TRUE)
 		{
@@ -1759,7 +1812,10 @@ FileRep_InsertConfigLogEntryInternal(char		*description,
 	struct timeval	logTime;
 	uint32		halfLength = (fileRepConfigLogShmem->logEnd - fileRepConfigLogShmem->logBegin) / 2;
 
-	if (Debug_filerep_config_print)
+	if (!Debug_filerep_config_print)
+		return;
+
+	if (log_filerep_to_syslogger)
 	{
 		ereport(LOG,
 				(errmsg("'%s', "

src/backend/cdb/cdbfilerepmirror.c

@@ -390,22 +390,6 @@ FileRepMirror_RunReceiver(void)
 											   "",	//databaseName
 											   ""); // tableName
 #endif				
-				
-				if (Debug_filerep_print)
-				{
-					fileRepProcIndex = msgType;
-					ereport(LOG,
-							(errmsg("M_RunReceiver "
-									"local count '%d' position insert '%p' msg length '%u' "
-									"consumer proc index '%d' ",
-									spareField,
-									msgPositionInsert,
-									msgLength,
-									msgType),
-							 FileRep_errdetail_Shmem(),
-							 FileRep_errcontext()));	
-				}
-				
 				fileRepShmemMessageDescr = (FileRepShmemMessageDescr_s*) msgPositionInsert;	
 		
 				/* it is not in use */
@@ -818,20 +802,6 @@ FileRepMirror_RunConsumer(void)
 							   spare,
 							   fileRepMessageHeader->messageCount);		
 		
-		if (Debug_filerep_print)
-			ereport(LOG,
-				(errmsg("M_RunConsumer msg header count '%d' local count '%d' "
-						"consumer proc index '%d'",
-						fileRepMessageHeader->messageCount,
-						spare,
-						fileRepProcIndex),
-				 FileRep_errdetail(fileRepMessageHeader->fileRepIdentifier,
-								   fileRepMessageHeader->fileRepRelationType,
-								   fileRepMessageHeader->fileRepOperation,
-								   fileRepMessageHeader->messageCount),
-				 FileRep_errdetail_Shmem(),
-				 FileRep_errcontext()));		
-	
 		spare = fileRepMessageHeader->messageCount;
 		
 		/* fileName is relative path to $PGDATA directory */

src/backend/cdb/cdbfilerepmirrorack.c

@@ -169,21 +169,6 @@ FileRepAckMirror_ConstructAndInsertMessage(
 						   FILEREP_UNDEFINED,
 						   fileRepMessageHeader->messageCount);	
 
-	if (Debug_filerep_print)
-		ereport(LOG,
-				(errmsg("M_ConstructAndInsertMessageAck construct and insert ack message "
-						"msg header crc '%u' message body length '%d' position insert '%p' ack state '%s' ",
-						fileRepMessageHeaderCrcLocal,
-						messageBodyLength,
-						msgPositionInsert,
-						FileRepAckStateToString[fileRepAckState]),
-				 FileRep_errdetail(fileRepIdentifier,
-								   fileRepRelationType,
-								   fileRepOperation,
-								   fileRepMessageHeader->messageCount),
-				 FileRep_errdetail_ShmemAck(),
-				 FileRep_errcontext()));			
-	
 	if (messageBodyLength)
 	{
 		fileRepMessageBody = (char *) (msgPositionInsert + 

src/backend/cdb/cdbfilerepprimary.c

@@ -513,29 +513,6 @@ FileRepPrimary_ConstructAndInsertMessage(
 						   FILEREP_UNDEFINED,
 						   fileRepMessageHeader->messageCount);
 	
-	if (Debug_filerep_print)
-		ereport(LOG,
-			(errmsg("P_ConstructAndInsertMessage "
-					"msg header count '%d' msg header crc '%u' position insert '%p' "
-					"msg length '%u' data length '%u'"
-					"open file flags '%x' "
-					"truncate position '" INT64_FORMAT "' ",
-					fileRepMessageHeader->messageCount,
-					fileRepMessageHeaderCrcLocal,
-					msgPositionInsert,
-					msgLength,
-					dataLength,
-					(fileRepOperation == FileRepOperationOpen || fileRepOperation == FileRepOperationCreateAndOpen) ?
-					fileRepOperationDescription.open.fileFlags : 0,
-					(fileRepOperation == FileRepOperationTruncate) ?
-					fileRepOperationDescription.truncate.position : 0),
-			 FileRep_errdetail(fileRepIdentifier,
-							   fileRepRelationType,
-							   fileRepOperation,
-							   spareField),
-			 FileRep_errdetail_Shmem(),
-			 FileRep_errcontext()));		
-
 	if (dataLength > 0)
 	{
 		fileRepMessageBody = (char *) (msgPositionInsert + 
@@ -993,22 +970,6 @@ FileRepPrimary_MirrorWrite(FileRepIdentifier_u		fileRepIdentifier,
 								   FILEREP_UNDEFINED,
 								   fileRepMessageHeader->messageCount);			
 						
-			if (Debug_filerep_print)
-				ereport(LOG,
-					(errmsg("P_ConstructAndInsertMessage "
-							"msg header count '%d' msg header crc '%u' position insert '%p' "
-							"msg body crc '%u' ",
-							fileRepMessageHeader->messageCount,
-							fileRepMessageHeaderCrcLocal,
-							msgPositionInsert,
-							fileRepMessageHeader->fileRepMessageBodyCrc),
-					 FileRep_errdetail(fileRepIdentifier,
-									   fileRepRelationType,
-									   FileRepOperationWrite,
-									   spareField),
-					 FileRep_errdetail_Shmem(),
-					 FileRep_errcontext()));					
-			
 			/* Copy Data */
 			fileRepMessageBody = (char *) (msgPositionInsert + 
 								sizeof(FileRepMessageHeader_s) + 
@@ -1753,18 +1714,6 @@ FileRepPrimary_RunSender(void)
 							   spare,
 							   fileRepMessageHeader->messageCount);					
 		
-		if (Debug_filerep_print)
-			ereport(LOG,
-				(errmsg("P_RunSender msg header count '%d' local count '%d' ",
-						fileRepMessageHeader->messageCount,
-						spare),
-				 FileRep_errdetail(fileRepMessageHeader->fileRepIdentifier,
-								   fileRepMessageHeader->fileRepRelationType,
-								   fileRepMessageHeader->fileRepOperation,
-								   fileRepMessageHeader->messageCount),
-				 FileRep_errdetail_Shmem(),
-				 FileRep_errcontext()));				
-		
 		spare = fileRepMessageHeader->messageCount;
 	
 		switch (fileRepMessageHeader->fileRepRelationType)

src/backend/cdb/cdbfilerepprimaryack.c

@@ -351,13 +351,6 @@ FileRepAckPrimary_RunReceiver(void)
 							   spareField,
 							   FILEREP_UNDEFINED);			
 		
-		if (Debug_filerep_print)
-			ereport(LOG,
-					(errmsg("P_RunReceiver ack msg header count '%d' ",
-							spareField),
-					 FileRep_errdetail_ShmemAck(),
-					 FileRep_errcontext()));				
-				
 	} // while(1)
 	
 	FileRepConnServer_CloseConnection();
@@ -1189,18 +1182,6 @@ FileRepAckPrimary_RunConsumer(void)
 							   FILEREP_UNDEFINED,
 							   fileRepMessageHeader->messageCount);				
 		
-		if (Debug_filerep_print)
-			ereport(LOG,
-				(errmsg("P_RunConsumer ack msg header count '%d' ack state '%s' ",
-						fileRepMessageHeader->messageCount,
-						FileRepAckStateToString[fileRepMessageHeader->fileRepAckState]),
-				 FileRep_errdetail(fileRepMessageHeader->fileRepIdentifier,
-								   fileRepMessageHeader->fileRepRelationType,
-								   fileRepMessageHeader->fileRepOperation,
-								   fileRepMessageHeader->messageCount),
-				 FileRep_errdetail_ShmemAck(),
-				 FileRep_errcontext()));		
-
 		if (status != STATUS_OK) {
 			break;
 		}

src/backend/storage/file/fd.c

@@ -1199,23 +1199,6 @@ FileWrite(File file, char *buffer, int amount)
 			   file, VfdCache[file].fileName,
 			   VfdCache[file].seekPos, amount, buffer));
 
-	/* Added temporary for troubleshooting */
-	if (Debug_filerep_print)
-		elog(LOG, "FileWrite: %d (%s) " INT64_FORMAT " %d %p",
-		 file, VfdCache[file].fileName,
-		 VfdCache[file].seekPos, amount, buffer);
-	else
-		FileRep_InsertLogEntry(
-							   "FileWrite",
-							   FileRep_GetFlatFileIdentifier(VfdCache[file].fileName, ""),
-							   FileRepRelationTypeFlatFile,
-							   FileRepOperationWrite,
-							   FILEREP_UNDEFINED,
-							   FILEREP_UNDEFINED,
-							   FileRepAckStateNotInitialized,
-							   VfdCache[file].seekPos,
-							   amount);
-
 	returnCode = FileAccess(file);
 	if (returnCode < 0)
 		return returnCode;

src/backend/utils/misc/guc_gp.c

@@ -266,6 +266,7 @@ bool		filerep_inject_listener_fault = false;
 bool		filerep_inject_db_startup_fault = false;
 bool		filerep_inject_change_tracking_recovery_fault = false;
 bool		filerep_mirrorvalidation_during_resync = false;
+bool		log_filerep_to_syslogger = false;
 
 /* WAL based replication debug GUCs */
 bool		debug_walrepl_snd = false;
@@ -2335,6 +2336,16 @@ struct config_bool ConfigureNamesBool_gp[] =
 		false, NULL, NULL
 	},
 
+	{
+		{"log_filerep_to_syslogger", PGC_SUSET, DEVELOPER_OPTIONS,
+			gettext_noop("log all filerep related log messages to the server log files"),
+			NULL,
+			GUC_NO_SHOW_ALL | GUC_NOT_IN_SAMPLE
+		},
+		&log_filerep_to_syslogger,
+		true, NULL, NULL
+	},
+
 	{
 		{"debug_filerep_gcov", PGC_SUSET, DEVELOPER_OPTIONS,
 			gettext_noop("workaround for filerep gcov issue"),
@@ -2352,7 +2363,7 @@ struct config_bool ConfigureNamesBool_gp[] =
 			GUC_NO_SHOW_ALL | GUC_NOT_IN_SAMPLE
 		},
 		&Debug_filerep_config_print,
-		false, NULL, NULL
+		true, NULL, NULL
 	},
 
 	{

src/include/utils/guc.h

@@ -227,6 +227,7 @@ extern bool filerep_inject_listener_fault;
 extern bool filerep_inject_db_startup_fault;
 extern bool filerep_inject_change_tracking_recovery_fault;
 extern bool filerep_mirrorvalidation_during_resync;
+extern bool log_filerep_to_syslogger;
 extern bool gp_crash_recovery_suppress_ao_eof;
 extern bool Debug_check_for_invalid_persistent_tid;
 extern bool gp_create_table_random_default_distribution;