Re: [HACKERS] [GENERAL] 8.1.4 - problem with PITR - .backup.done / backup.ready version of the same file at the same time.
Rafael Martinez, Guerrero [EMAIL PROTECTED] writes: The problem was that 000100080010.0006D5E8.backup was already archived, but under pg_xlog/archive_status/ there were two files: - 000100080010.0006D5E8.backup.done 000100080010.0006D5E8.backup.ready - This situation should not happen, anyone has seen this problem before? No, it shouldn't. What I suspect is that XLogArchiveIsDone() got confused and created a duplicate .ready file. It basically assumes that the only way its stat() calls can fail is ENOENT, ie, file not there ... but I wonder if they failed for some other reason instead. What sort of platform and filesystem is this on? Did you happen to make note of the mod times of the two files before deleting them? regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] [GENERAL] 8.1.4 - problem with PITR - .backup.done /
On Tue, 2006-05-30 at 09:45 -0400, Tom Lane wrote: Rafael Martinez, Guerrero [EMAIL PROTECTED] writes: The problem was that 000100080010.0006D5E8.backup was already archived, but under pg_xlog/archive_status/ there were two files: - 000100080010.0006D5E8.backup.done 000100080010.0006D5E8.backup.ready - This situation should not happen, anyone has seen this problem before? No, it shouldn't. What I suspect is that XLogArchiveIsDone() got confused and created a duplicate .ready file. It basically assumes that the only way its stat() calls can fail is ENOENT, ie, file not there ... but I wonder if they failed for some other reason instead. What sort of platform and filesystem is this on? This is on a AMD64 Opteron server with RHELAS4 / 2.6.9-34.ELsmp and ext3 filesystem. This is the first time this happens. I cannot the postgres internals but after a quick look to the source code .. XLogArchiveIsDone() has this code in the final of the function: - /* Race condition --- maybe archiver just finished, so recheck */ StatusFilePath(archiveStatusPath, xlog, .done); if (stat(archiveStatusPath, stat_buf) == 0) return true; /* Retry creation of the .ready file */ XLogArchiveNotify(xlog); return false; } - What happens if we have a race condition and the archiver creates a .done file between the last check for the .done file and the creation of the .ready file by XLogArchiveNotify? Did you happen to make note of the mod times of the two files before deleting them? No, I did not :( If it happens again, I will do. regards, -- Rafael Martinez, [EMAIL PROTECTED] Center for Information Technology Services University of Oslo, Norway PGP Public Key: http://folk.uio.no/rafael/ ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [HACKERS] [GENERAL] 8.1.4 - problem with PITR - .backup.done / backup.ready version of the same file at the same time.
Rafael Martinez [EMAIL PROTECTED] writes: What happens if we have a race condition and the archiver creates a .done file between the last check for the .done file and the creation of the .ready file by XLogArchiveNotify? That can't happen; the archiver creates the .done file by rename()ing the previous .ready file, which is (supposed to be) an atomic action. If the .ready file isn't there, and then after that we see that the .done file isn't there, then either neither of them are there or the filesystem is seriously broken. My thought is that the stat()s on the .done file failed for some obscure reason, perhaps insufficient kernel resources, even though the file was actually there. If you have postmaster log output for the interval in which this happened, it would be interesting to look for occurrences of this warning message from pgarch_archiveDone: if (rename(rlogready, rlogdone) 0) ereport(WARNING, (errcode_for_file_access(), errmsg(could not rename file \%s\ to \%s\: %m, rlogready, rlogdone))); If you find any then we might need a different theory ... regards, tom lane ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [HACKERS] [GENERAL] 8.1.4 - problem with PITR - .backup.done /
On Tue, 2006-05-30 at 15:38 -0400, Tom Lane wrote: [...] My thought is that the stat()s on the .done file failed for some obscure reason, perhaps insufficient kernel resources, even though the file was actually there. If you have postmaster log output for the interval in which this happened, it would be interesting to look for occurrences of this warning message from pgarch_archiveDone: if (rename(rlogready, rlogdone) 0) ereport(WARNING, (errcode_for_file_access(), errmsg(could not rename file \%s\ to \%s\: %m, rlogready, rlogdone))); If you find any then we might need a different theory ... I do not find any warning message could not rename file These are the relevant entries in the log file: [2006-05-29 17:31:55.212 CEST] 12022 LOG: archived transaction log file 00010008000F PITR_basebackup script started around 17:32 [2006-05-29 17:40:27.735 CEST] 12022 LOG: archived transaction log file 000100080010 [2006-05-29 17:49:32.075 CEST] 12022 LOG: archived transaction log file 000100080011 [2006-05-29 17:59:40.575 CEST] 12022 LOG: archived transaction log file 000100080012 [2006-05-29 18:08:27.229 CEST] 12022 LOG: archived transaction log file 000100080013 [2006-05-29 18:11:36.434 CEST] 12022 LOG: archived transaction log file 000100080010.0006D5E8.backup [2006-05-29 18:11:36.467 CEST] 12022 LOG: archive command archive_wal.sh -P pg_xlog/000100080010.0006D5E8.backup -F 000100080010.0006D5E8.backup failed: return code 256 [2006-05-29 18:11:37.479 CEST] 12022 LOG: archive command archive_wal.sh -P pg_xlog/000100080010.0006D5E8.backup -F 000100080010.0006D5E8.backup failed: return code 256 [2006-05-29 18:11:38.492 CEST] 12022 LOG: archive command archive_wal.sh -P pg_xlog/000100080010.0006D5E8.backup -F 000100080010.0006D5E8.backup failed: return code 256 [2006-05-29 18:11:38.492 CEST] 12022 WARNING: transaction log file 000100080010.0006D5E8.backup could not be archived: too many failures PITR_basebackup script finnished 18:12:16 ... Same error several times until we deleted the .backup.ready file at 18:15 [2006-05-29 18:19:14.546 CEST] 12022 LOG: archived transaction log file 000100080014 [2006-05-29 18:30:10.939 CEST] 12022 LOG: archived transaction log file 000100080015 ... Our PITR_basebackup script does this: * Checks if Backup label file exists * Starts Backup process with pg_start_backup() * Creates a LVM2 Snapshot of data partition * Mounts the Snapshot partition * Creates a tar.bz2 file of data * Umounts Snapshot partition * Removes Snapshot LV * Backup last WAL file not yet archived * Stops Backup process with pg_stop_backup() * Waits for *.backup file to appear under the archivedir * Removes old WAL archived files * Removes old tar.bz2 data file To create the tar.bz file and to delete old WAL files can take some time. The total running time of the PITR_basebackup script was 2412 sec. If we get the same problem again, I will try to get more information from the system. As I said in my last e-mail, this has been a one time problem. regards, -- Rafael Martinez, [EMAIL PROTECTED] Center for Information Technology Services University of Oslo, Norway PGP Public Key: http://folk.uio.no/rafael/ ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
