Quote:
|
For starters, we are back to the time to build or rebuild a RAID 5 array. With 250 GB drives, it takes 5 or so hours. With the 320 GB drives, it takes 24 hours (without doing any copying or use). This is an indicator something "strange" is going on. It just doesn't add up. Does this mean the the SNAP is having a difficult time with the build/rebuild? If so, what kind of difficulty? Is it actually working, or does it just "look like" it is working properly? Nothing for sure here, just an indicator.
|
Ok, I think I have a clue.
I broke down and "broke" the raid, because I got so much help here, that I feel I owe something. Hopefully this will answer some questions.
The raid is rebuilding. It's just over half used - something like 450GB. Get this, it's taking exactly as long to rebuild as it did on an empty disk - almost exactly 24 hours. I think I found the reason it's longer with larger drives. It's highlighted in red below. The short answer is that it is using swap space because it can not allocate enough memory for an rcd_lncnt. - that's my semi-educated guess.
secondly the TB limit might be caused by the size of the i-node table. hummmm, i-node tables should be related to the number of files on the disk.... or is it just a static cache based on disk size... hummm... Damn, I'm going to have to fill the disk and break it again. I was going to say.... never mind. I'll get back to you.
Lets here your thoughts.
oidar
09/25/2006 22:57:15 Command: info log Temporary
Requested: Log=Temporary, Boot=N/A Direction=Fwd Types=All Source=All
09/24/2006 22:41:53 35 S SYS | System Initialization : Server v4.0.860
Build Date: Mar 2 2005 17:50:35
Boot Count: 35
09/24/2006 22:41:53 35 D SYS | Executable built by KEVIN
09/24/2006 22:41:53 35 D SYS | Hardware platform:2.0.1 Model:2 (256 MBytes) S/N:30xxxx
09/24/2006 22:41:53 35 D SYS | ETH: Reset- Eaddr set to 00 xx B6 04 xx xx
09/24/2006 22:41:53 35 D SYS | Update IP...
09/24/2006 22:41:54 35 D SYS | Initial file system BIO cache size is 26838528 bytes, 3232 buffers
09/24/2006 22:41:54 35 D SYS | DISK: Initial ARBs: 3232 Memory: 530048
09/24/2006 22:41:54 35 D SYS | Code Page set to 437
09/24/2006 22:41:54 35 D SYS | QDL System is DISABLED
09/24/2006 22:41:54 35 D SYS | Disk cache flush enabled
09/24/2006 22:41:54 35 D SYS | SNMP agent disabled.
09/24/2006 22:41:54 35 D SYS | SNTP disabled.
09/24/2006 22:41:54 35 D SYS | AFP: not started
09/24/2006 22:41:54 35 D SYS | FTPD: 'FTPD' not started.
09/24/2006 22:41:54 35 D SYS | Update WorkGroup...
09/24/2006 22:41:59 35 D SYS | Intf: 0, dev: 0: Model: ST3320620A
09/24/2006 22:41:59 35 D SYS | Firmware Rev: 3.AAD Serial #: 5QF0H0GS
09/24/2006 22:41:59 35 D SYS | Intf: 0, dev: 1: Model: ST3320620A
09/24/2006 22:41:59 35 D SYS | Firmware Rev: 3.AAD Serial #: 5QF0GZ5P
09/24/2006 22:41:59 35 D SYS | Intf: 1, dev: 0: Model: ST3320620A
09/24/2006 22:41:59 35 D SYS | Firmware Rev: 3.AAD Serial #: 5QF0GSDJ
09/24/2006 22:41:59 35 D SYS | Intf: 1, dev: 1: Model: ST3320620A
09/24/2006 22:41:59 35 D SYS | Firmware Rev: 3.AAD Serial #: 5QF0FHMP
09/24/2006 22:41:59 35 E L01 | File System : Logical set member 1 not found. Original device ID: 60000
09/24/2006 22:41:59 35 W L01 | File System : 1 member(s) missing in logical device (original ID: 60000)
09/24/2006 22:41:59 35 D SYS | RAID5Initialize: creating 64 worker threads
09/24/2006 22:41:59 35 D SYS | RAID5InitSet: device 1 unavailable to initialize set
09/24/2006 22:41:59 35 D SYS | RAID5InitializeCache: allocated cache of 65526KB
09/24/2006 22:41:59 35 I L00 | File System Check : Executing fsck /dev/ride0g /fix /fixfatal
09/24/2006 22:41:59 35 I L00 | File System Check : partition is clean.
09/24/2006 22:41:59 35 D SYS | Update FDB 0x10006...
09/24/2006 22:41:59 35 I L00 | File System : Opened FDB for device 0x10006
09/24/2006 22:41:59 35 D SYS | Scheduled ACL Set and Propagate at /priv/os_private for FDB_ID_12
09/24/2006 22:41:59 35 I L00 | File System Check : Executing fsck /dev/ride1g /fix /fixfatal
09/24/2006 22:41:59 35 D SYS | Propagate on /priv/os_private: Success - 8 files, 0 dirs; Errors - 0 files, 0 dirs
09/24/2006 22:41:59 35 I L00 | File System Check : partition is clean.
09/24/2006 22:41:59 35 D SYS | Update FDB 0x1000E...
09/24/2006 22:41:59 35 I L00 | File System : Opened FDB for device 0x1000E
09/24/2006 22:41:59 35 D SYS | Scheduled ACL Set and Propagate at /pri2/os_private for FDB_ID_13
09/24/2006 22:41:59 35 I L01 | File System Check : Executing fsck /dev/rraid0 /force /fix /fixfatal
09/24/2006 22:41:59 35 D SYS | Propagate on /pri2/os_private: Success - 8 files, 0 dirs; Errors - 0 files, 0 dirs
09/24/2006 22:41:59 35 I L01 | File System Check : partition is clean.
09/24/2006 22:41:59 35 D SYS | Fsck - Using primary superblock
09/24/2006 22:42:00 35 D SYS | 150674960 bytes pre-allocated
09/24/2006 22:42:01 35 D SYS | Memory allocation for i-node cache: 90% of free RAM
09/24/2006 22:42:02 35 D L01 | File System Check : Failed to allocate 174884354 bytes for rcd_lncntp!!!
09/24/2006 22:42:03 35 D SYS | -- Swap-based Fsck --09/24/2006 22:42:03 35 D SYS | 26414 i-node cache blocks, cache hash table: 12281 entries
09/24/2006 22:42:03 35 D SYS | 256 i-nodes per generic cache block
09/24/2006 22:42:03 35 D SYS | 170 i-nodes per directory cache block
09/24/2006 22:42:03 35 I L01 | File System Check : ** Phase 1 - Check blocks and sizes
09/24/2006 22:42:04 35 I NET | DHCP: T1 length was 0 is now 302400
09/24/2006 22:42:04 35 I NET | DHCP: T2 length was 0 is now 453600
09/24/2006 22:42:04 35 I NET | DHCP/BOOTP: Setting IP address to xx.xx.xx.xx
09/24/2006 22:42:04 35 D SYS | Update IP...
09/24/2006 22:42:04 35 D SYS | BOOTP: DNS = 200A3C03
09/24/2006 22:43:57 35 D SMB | SMB : Becoming master browser for xxx
09/24/2006 23:31:35 35 D SYS | Created shadow FDB files
09/24/2006 23:31:35 35 I L00 | File System : Closed FDB for device 0x1000E
09/24/2006 23:31:36 35 D SYS | Failed to copy (2), skipping tag.dat
09/24/2006 23:31:36 35 D SYS | Compared times file1Secs (451750DE) file2Secs (45174FD9)
09/24/2006 23:31:36 35 D SYS | Copy private FS /priv/tag.dat to /pri2/tag.dat = pass
09/24/2006 23:31:36 35 D SYS | Cloned private FS from 10006 to 1000E
09/24/2006 23:31:36 35 I D01 | File System : Spare Device 10008 has been converted from Individual Drive.
09/24/2006 23:31:36 35 D SYS | Spare Device 10008 has been created and will be used momentarily.
09/25/2006 0:01:31 35 I L01 | File System Check : ** Phase 1b - Rescan for more duplicate blocks
09/25/2006 0:01:31 35 I L01 | File System Check : ** Phase 2 - Check pathnames
09/25/2006 0:02:34 35 I L01 | File System Check : ** Phase 3 - Check connectivity
09/25/2006 0:02:34 35 I L01 | File System Check : ** Phase 4 - Check reference counts
09/25/2006 0:03:00 35 I L01 | File System Check : ** Phase 4b - Check backlinks
09/25/2006 0:03:54 35 I L01 | File System Check : ** Phase 5 - Check cylinder groups
09/25/2006 0:35:56 35 D SYS | 150676124 bytes used during fsck()
09/25/2006 0:35:56 35 I L01 | File System Check : 66886 files, 58210492 used, 56784693 free (0 frags, 56784693 blocks, 0.0%% fragmentation)
09/25/2006 0:35:56 35 D SYS | Elapsed time: 6837 s.
09/25/2006 0:35:56 35 D SYS | Fsck cache statistics:
09/25/2006 0:35:56 35 D SYS | total memory used for cache: 119910736 bytes
09/25/2006 0:35:56 35 D SYS | total number of directories: 7793
09/25/2006 0:35:56 35 D SYS | maximum depth of recursion in sorting: 1
09/25/2006 0:35:56 35 D SYS | number of swaps in sorting phase: 13976
09/25/2006 0:35:56 35 D SYS | ----- generic i-node cache -----
09/25/2006 0:35:56 35 D SYS | cache entries: 35218
09/25/2006 0:35:56 35 D SYS | cache hits: 203744218 (99%)
09/25/2006 0:35:56 35 D SYS | cache misses: 740182 (0%)
09/25/2006 0:35:56 35 D SYS | reused cache entries: 713768
09/25/2006 0:35:56 35 D SYS | total reads from swap device: 398611
09/25/2006 0:35:56 35 D SYS | total writes to swap device: 349364
09/25/2006 0:35:56 35 D SYS | total writes skipped (clean blocks): 364404
09/25/2006 0:35:56 35 D SYS | average successful cache lookup: 1.00 iterations
09/25/2006 0:35:56 35 D SYS | maximum successful cache lookup: 1 iterations
09/25/2006 0:35:56 35 D SYS | average unsuccessful cache lookup: 1.00 iterations
09/25/2006 0:35:56 35 D SYS | maximum unsuccessful cache lookup: 1 iterations
09/25/2006 0:35:56 35 D SYS | ----- directory i-node cache -----
09/25/2006 0:35:56 35 D SYS | cache entries: 17610
09/25/2006 0:35:56 35 D SYS | cache hits: 138928 (99%)
09/25/2006 0:35:56 35 D SYS | cache misses: 45 (0%)
09/25/2006 0:35:56 35 D SYS | reused cache entries: 91
09/25/2006 0:35:56 35 D SYS | total reads from swap device: 45
09/25/2006 0:35:56 35 D SYS | total writes to swap device: 91
09/25/2006 0:35:56 35 D SYS | total writes skipped (clean blocks): 0
09/25/2006 0:35:56 35 D SYS | average successful cache lookup: 1.00 iterations
09/25/2006 0:35:56 35 D SYS | maximum successful cache lookup: 1 iterations
09/25/2006 0:35:56 35 D SYS | average unsuccessful cache lookup: 1.00 iterations
09/25/2006 0:35:56 35 D SYS | maximum unsuccessful cache lookup: 1 iterations
09/25/2006 0:35:56 35 I L01 | File System Check : Cleanup completed...
09/25/2006 0:35:56 35 D SYS | Update FDB 0x60000...
09/25/2006 0:35:56 35 I L01 | File System : Opened FDB for device 0x60000
09/25/2006 0:35:56 35 D SYS | Scheduled ACL Set and Propagate at /0/os_private for FDB_ID_0
09/25/2006 0:35:56 35 I L00 | File System Check : Executing fsck /dev/ride1g /fix /fixfatal
09/25/2006 0:35:56 35 D SYS | Propagate on /0/os_private: Success - 13 files, 0 dirs; Errors - 0 files, 0 dirs
09/25/2006 0:35:56 35 I L00 | File System Check : partition is clean.
09/25/2006 0:35:57 35 D SYS | Failed to copy (2), skipping tag.dat
09/25/2006 0:35:57 35 D SYS | Compared times file1Secs (45175BB8) file2Secs (451750DE)
09/25/2006 0:35:57 35 D SYS | Copy private FS /priv/tag.dat to /pri2/tag.dat = pass
09/25/2006 0:35:57 35 D SYS | Cloned private FS from 10006 to 1000E
09/25/2006 0:35:57 35 D SYS | Update FDB 0x1000E...
09/25/2006 0:35:57 35 I L00 | File System : Opened FDB for device 0x1000E
09/25/2006 0:35:57 35 D SYS | Scheduled ACL Set and Propagate at /pri2/os_private for FDB_ID_13
09/25/2006 0:35:57 35 D SYS | Propagate on /pri2/os_private: Success - 8 files, 0 dirs; Errors - 0 files, 0 dirs
09/25/2006 0:35:57 35 D SYS | NFS: The hash table has been initialized.
09/25/2006 0:35:57 35 D SYS | NFS: the NFSID <--->FDBID cache has been initialised.
09/25/2006 0:35:57 35 D SYS | NFS Server started.
09/25/2006 0:35:57 35 D SYS | suspend_factor = E3A0E
09/25/2006 0:35:57 35 D SYS | DISK: Additional ARBs: 18441 (Mem: 3024324) Total Arbs: 21673 (Mem: 3554372)
09/25/2006 0:35:57 35 I SYS | System Initialization : Initialization Complete! Memory to be released: 153134064 bytes.
09/25/2006 0:35:57 35 D SYS | Restarted process timing
09/25/2006 0:35:57 35 W D[80060000] | File System : Logical device 80060000: no spares found to perform hot replacement
09/25/2006 0:36:06 35 D SYS | RAID5ReplaceMember on array 0: started (device = 0x80010008, buffer size = 64KB)
09/25/2006 0:50:24 35 D SYS | RAID5ReplaceMember on array 0: 1% done
09/25/2006 1:04:36 35 D SYS | RAID5ReplaceMember on array 0: 2% done
09/25/2006 1:18:48 35 D SYS | RAID5ReplaceMember on array 0: 3% done
09/25/2006 1:33:00 35 D SYS | RAID5ReplaceMember on array 0: 4% done
09/25/2006 1:47:13 35 D SYS | RAID5ReplaceMember on array 0: 5% done
09/25/2006 2:01:25 35 D SYS | RAID5ReplaceMember on array 0: 6% done
09/25/2006 2:15:37 35 D SYS | RAID5ReplaceMember on array 0: 7% done
09/25/2006 2:29:49 35 D SYS | RAID5ReplaceMember on array 0: 8% done
09/25/2006 2:44:01 35 D SYS | RAID5ReplaceMember on array 0: 9% done
09/25/2006 2:58:13 35 D SYS | RAID5ReplaceMember on array 0: 10% done
09/25/2006 3:12:26 35 D SYS | RAID5ReplaceMember on array 0: 11% done
09/25/2006 3:26:38 35 D SYS | RAID5ReplaceMember on array 0: 12% done
09/25/2006 3:40:50 35 D SYS | RAID5ReplaceMember on array 0: 13% done
09/25/2006 3:55:04 35 D SYS | RAID5ReplaceMember on array 0: 14% done
09/25/2006 4:09:17 35 D SYS | RAID5ReplaceMember on array 0: 15% done
09/25/2006 4:23:30 35 D SYS | RAID5ReplaceMember on array 0: 16% done
09/25/2006 4:37:42 35 D SYS | RAID5ReplaceMember on array 0: 17% done
09/25/2006 4:51:56 35 D SYS | RAID5ReplaceMember on array 0: 18% done
09/25/2006 5:06:09 35 D SYS | RAID5ReplaceMember on array 0: 19% done
09/25/2006 5:20:22 35 D SYS | RAID5ReplaceMember on array 0: 20% done
09/25/2006 5:34:34 35 D SYS | RAID5ReplaceMember on array 0: 21% done
09/25/2006 5:48:48 35 D SYS | RAID5ReplaceMember on array 0: 22% done
09/25/2006 6:03:02 35 D SYS | RAID5ReplaceMember on array 0: 23% done
09/25/2006 6:17:15 35 D SYS | RAID5ReplaceMember on array 0: 24% done
09/25/2006 6:31:28 35 D SYS | RAID5ReplaceMember on array 0: 25% done
09/25/2006 6:45:43 35 D SYS | RAID5ReplaceMember on array 0: 26% done
09/25/2006 6:59:57 35 D SYS | RAID5ReplaceMember on array 0: 27% done
09/25/2006 7:14:10 35 D SYS | RAID5ReplaceMember on array 0: 28% done
09/25/2006 7:28:24 35 D SYS | RAID5ReplaceMember on array 0: 29% done
09/25/2006 7:42:39 35 D SYS | RAID5ReplaceMember on array 0: 30% done
09/25/2006 7:56:54 35 D SYS | RAID5ReplaceMember on array 0: 31% done
09/25/2006 8:11:08 35 D SYS | RAID5ReplaceMember on array 0: 32% done
09/25/2006 8:25:23 35 D SYS | RAID5ReplaceMember on array 0: 33% done
09/25/2006 8:39:37 35 D SYS | RAID5ReplaceMember on array 0: 34% done
09/25/2006 8:53:53 35 D SYS | RAID5ReplaceMember on array 0: 35% done
09/25/2006 9:08:07 35 D SYS | RAID5ReplaceMember on array 0: 36% done
09/25/2006 9:22:22 35 D SYS | RAID5ReplaceMember on array 0: 37% done
09/25/2006 9:36:37 35 D SYS | RAID5ReplaceMember on array 0: 38% done
09/25/2006 9:50:53 35 D SYS | RAID5ReplaceMember on array 0: 39% done
09/25/2006 10:05:08 35 D SYS | RAID5ReplaceMember on array 0: 40% done
09/25/2006 10:19:23 35 D SYS | RAID5ReplaceMember on array 0: 41% done
09/25/2006 10:33:39 35 D SYS | RAID5ReplaceMember on array 0: 42% done
09/25/2006 10:47:56 35 D SYS | RAID5ReplaceMember on array 0: 43% done
09/25/2006 11:02:12 35 D SYS | RAID5ReplaceMember on array 0: 44% done
09/25/2006 11:16:28 35 D SYS | RAID5ReplaceMember on array 0: 45% done
09/25/2006 11:30:44 35 D SYS | RAID5ReplaceMember on array 0: 46% done
09/25/2006 11:45:02 35 D SYS | RAID5ReplaceMember on array 0: 47% done
09/25/2006 11:59:19 35 D SYS | RAID5ReplaceMember on array 0: 48% done
09/25/2006 12:13:36 35 D SYS | RAID5ReplaceMember on array 0: 49% done
09/25/2006 12:28:01 35 D SYS | RAID5ReplaceMember on array 0: 50% done
09/25/2006 12:42:20 35 D SYS | RAID5ReplaceMember on array 0: 51% done
09/25/2006 12:56:37 35 D SYS | RAID5ReplaceMember on array 0: 52% done
09/25/2006 13:10:55 35 D SYS | RAID5ReplaceMember on array 0: 53% done
09/25/2006 13:25:13 35 D SYS | RAID5ReplaceMember on array 0: 54% done
09/25/2006 13:39:31 35 D SYS | RAID5ReplaceMember on array 0: 55% done
09/25/2006 13:53:50 35 D SYS | RAID5ReplaceMember on array 0: 56% done
09/25/2006 14:08:09 35 D SYS | RAID5ReplaceMember on array 0: 57% done
09/25/2006 14:22:28 35 D SYS | RAID5ReplaceMember on array 0: 58% done
09/25/2006 14:36:48 35 D SYS | RAID5ReplaceMember on array 0: 59% done
09/25/2006 14:51:09 35 D SYS | RAID5ReplaceMember on array 0: 60% done
09/25/2006 15:05:29 35 D SYS | RAID5ReplaceMember on array 0: 61% done
09/25/2006 15:19:49 35 D SYS | RAID5ReplaceMember on array 0: 62% done
09/25/2006 15:34:10 35 D SYS | RAID5ReplaceMember on array 0: 63% done
09/25/2006 15:48:32 35 D SYS | RAID5ReplaceMember on array 0: 64% done
09/25/2006 16:02:53 35 D SYS | RAID5ReplaceMember on array 0: 65% done
09/25/2006 16:17:14 35 D SYS | RAID5ReplaceMember on array 0: 66% done
09/25/2006 16:31:36 35 D SYS | RAID5ReplaceMember on array 0: 67% done
09/25/2006 16:46:00 35 D SYS | RAID5ReplaceMember on array 0: 68% done
09/25/2006 17:00:23 35 D SYS | RAID5ReplaceMember on array 0: 69% done
09/25/2006 17:14:46 35 D SYS | RAID5ReplaceMember on array 0: 70% done
09/25/2006 17:29:09 35 D SYS | RAID5ReplaceMember on array 0: 71% done
09/25/2006 17:43:33 35 D SYS | RAID5ReplaceMember on array 0: 72% done
09/25/2006 17:57:59 35 D SYS | RAID5ReplaceMember on array 0: 73% done
09/25/2006 18:12:24 35 D SYS | RAID5ReplaceMember on array 0: 74% done
09/25/2006 18:26:50 35 D SYS | RAID5ReplaceMember on array 0: 75% done
09/25/2006 18:41:16 35 D SYS | RAID5ReplaceMember on array 0: 76% done
09/25/2006 18:55:42 35 D SYS | RAID5ReplaceMember on array 0: 77% done
09/25/2006 19:10:08 35 D SYS | RAID5ReplaceMember on array 0: 78% done
09/25/2006 19:24:36 35 D SYS | RAID5ReplaceMember on array 0: 79% done
09/25/2006 19:39:05 35 D SYS | RAID5ReplaceMember on array 0: 80% done
09/25/2006 19:53:35 35 D SYS | RAID5ReplaceMember on array 0: 81% done
09/25/2006 20:08:04 35 D SYS | RAID5ReplaceMember on array 0: 82% done
09/25/2006 20:22:34 35 D SYS | RAID5ReplaceMember on array 0: 83% done
09/25/2006 20:37:04 35 D SYS | RAID5ReplaceMember on array 0: 84% done
09/25/2006 20:51:37 35 D SYS | RAID5ReplaceMember on array 0: 85% done
09/25/2006 21:06:11 35 D SYS | RAID5ReplaceMember on array 0: 86% done
09/25/2006 21:20:44 35 D SYS | RAID5ReplaceMember on array 0: 87% done
09/25/2006 21:35:18 35 D SYS | RAID5ReplaceMember on array 0: 88% done
09/25/2006 21:49:52 35 D SYS | RAID5ReplaceMember on array 0: 89% done
09/25/2006 22:04:28 35 D SYS | RAID5ReplaceMember on array 0: 90% done
09/25/2006 22:19:06 35 D SYS | RAID5ReplaceMember on array 0: 91% done
09/25/2006 22:33:44 35 D SYS | RAID5ReplaceMember on array 0: 92% done
09/25/2006 22:48:23 35 D SYS | RAID5ReplaceMember on array 0: 93% done