afp server issue - very hign cpu load

Timothy, we have Allow simultaneous logins checked, as most users who access our server share the same login credentials (we don't have a need for hosting home directories), and we have the same AFS high CPU usage issue.

Actually, I can now say that having that checked and doing simultaneous logins will cause a problem every time. Unfortunately, having it unchecked doesn't prevent the problem. When my faculty and staff logged in Monday, CPU went to 30% and hasn't moved much since, even as the students started logging in today.
So I can replicate the problem with the simultaneous logins, but I can't prevent it.
Has anyone else tried the hint about disabling ""Allow Host Cache Flushing"."?

What problems does allowing simultaneous logins cause?

We have disabled Allow Host Cache Flushing on all XRAIDs. It did not make a lasting difference.

Well I don't have any more news that would help. I have been checking the net now for over 3 months on any news about these problems, and from what I can find, there is no solution.

At the moment running 10.5.5, does 10.5.6 help with any AFP trying to burn out the CPU?

We don't have many people logging in and we are having these issues.

Any solution??

I can confirm I am still having the same run-away-afp-cpu-load issues on 10.5.6 that I first started seeing on 10.5.5.

We work around it by rebooting the servers in the wee-hours. I disabled the reboot after upping to 10.5.6 (combo) and the problem came back within 2 days.

We don't use raid so that isn't a factor.

Like many users on this post, we still do not have a solution. I do feel that we have discovered the culprit. I believe the problem is when several users are using a Microsoft Office application (we have Office 2004), specifically Powerpoint at the same time.

We have tried most (if not all) the troubleshooting advice on this tread. Deleting .DS Store, redirecting certain folders, running disk utility, running disk warrior, etc. Some of the fixes (like deleting .DS Store) seemed to work temporarily. Lately we have seen AppleFileServer take over 700% of the CPU on our X Serve ( 2 x 2.8 Quad Core INtel Xeon, with 4 GB Ram OS 10.5.6). This is our fastest server of our 3 file servers. It hosts student data for about 1000 students (specifically grades 11 and 12). Recently, when we hit about 50-60 users we see the AppleFileServer spike to the level just mentioned. Of the 60 users, approximately 40 were using a Microsoft Office Product such as Word or Powerpoint. At other times, we see 90 plus users with no problem (I suspect they are only using a web browser (either Safari or Firefox). Coincidentally, several classes are doing Powerpoint projects at the end of the semester.

This morning, we replicated the situation when a class of approximately 25 came into a lab and attempted to open a Powerpoint. AppleFileServer (as it has the last week) jumped over 700 and stayed there. I asked the class to quit Powerpoint and open their file with Keynote. AppleFileServer went back down to single digits. At one time a student decided they didn't like Keynote and went back to Powerpoint and we saw the server spike.

My personal opinion is that it is when multiple users open up a Powerpoint (not Word) it causes AppleFileServer to jump and hang. I currently have 67 users on the server and the CPU is is staying in single digits. Most have Word open. The server did spike when it launched but didn't sit at the high level. I had two students open up Powerpoint and up went AppleFileServer. It didn't stay at the level for a real long time (maybe 2 minutes) but certainly did spike.

The next thing we will try is using a class of freshmen or sophomores (that are on a different server and have them open a Powerpoint file and see what it does to AppleFileServer.

After I give it a try, I will report it here.

One final note. On our third server, we have our teachers (about 200 accounts) typically we have over 90 users logged in with several (I would guess 10-15 teachers) using or showing a Powerpoint. The difference is, they are not all logging in at the same time and using it in the same way a lab full of students do.

If anyone else has a similar experience, please share it with us.

This afternoon, we tried a lab of 30 freshmen and sophomore students (on a different X Serve) and had them open powerpoint and it didn't hardly make a dent in the AppleFileServer. It only had about 30 users vs. the typical 60-90 users.

Our next attempt at a solution is to delete all the Library folders from the server with the spiking AppleFileServer.

Final note: It also spiked with about 75 users and no one (that I know of) using Powerpoint, but mostly using Word.

Could you post the specs of your server. Include OS, hardware setup, storage and the such.

It sounds like there is a similarity to the setup we have at our school.


Shawn

Okay will open this bag of worms...

This is what we have here...

------
*Part I:*
------

---------
xserve1.mydomain.com
2.8 Ghz Quad-Core Intel Xeon
8GB Memory
Mac OS X Server 10.5.5

Services are:

Primary DNS
OD Master

---------
xserve2.mydomain.com
2 x 2.3 Ghz PowerPC G5
8GB Memory
Mac OS X Server 10.5.5

Services are:

AFP (Homes)
xServe Raid 800GB Array (Raid 5) (Right Side)

---------
xserve3.mydomain.com
2.8Ghz Quad-Core Intel Xeon
8GB Memory

Services are:

AFP (Homes)
xServe Raid 800GB Array (Raid 5) (Left Side)

---------
xserve4.mydomain.com
2 x 2.0 Dual Core Intel Xeon
7GB Ram

Services are:

Secondary DNS
OD Slave

---------
xserve5.mydomain.com
2.8Ghz Quad-Core Intel Xeon
8GB Ram

Services are:

AFP (Group Share)
iCal Server (Not working)
Netboot (Ran only when I need it)
Software Update (Working)
Web Service (Wiki's and Blogs) (Working)

--------

Last but not least, on the upgrade list... but works fine

print.mydomain.com
1.3Ghz PowerPC G4
1.5GB RAM
500GB Mirrored Raid Array
10.4.11

Services:

Print

Running PaperCut for print management software, syncs with the OD Master, have a small application on clients, gives a update on how much they print.

-----------------
+*Additional Notes:*+
-----------------

+*Now before Nov 08, we had two less servers and half the RAM in each machine. Then we brought in Apple and company, which they encouraged us to get some more servers, RAM and moved our services around. After formatting and reinstalling each server, then creating a new OD Master and importing all users again, not the easy import, a "from scratch import" so we had reset all users passwords, and then updating clients to OS X 10.5.....*+

+*Get this*+

+*We are having still the same problems as we did before (might even be a bit worse)*+

+*Last week, we split the home folders, so rather then having 80+ Clients logging into one server, we moved 50% to one server and then left the other 50% on the original*+


----------
*Part II:*
----------


Clients


iMac 2.0Ghz
1GB RAM
220GB Hard Drive
100MB Network Connection
OS X 10.5.6

Office 2004
Adobe CS3

We are using NHR Redirector 3.02
More info
http://jochsner.dyndns.org/scripts/NHR.html


So network home users have the following redirected locally:

~/Library/Fonts to /Library/Fonts
~/Library/Caches is replaced by a symlink to /tmp

+I prefer a client side solution, it take a bit of work to get it all setup with the client, but we have been doing it since 10.4 and just continued. Not so sure how Office 2004 likes it when MCX solution screws around with the clients font folder....+



+So there you have it, what we are running and please note this is a new install, all the servers, everything a whole 48 hours to get everything perfect, and with the apple expert saying the whole way, "DNS DNS DNS DNS" and it will work+

+Even with the increase of hardware, still same problems.+

+*There is a problem, it needs to be fixed...*+

Shawn-I posted the specs in the post above. You can iChat bohnsackjay or skype jaybohnsack if you want to discuss further.

As I mentioned above, I still think the problem (at least for us) was corrupt Microsoft preferences.

Last night, we deleted all Library folders from the 1000 users on the server. We also deleted the Microsoft User folder in each document folder. This morning, we had the same class doing the same project that caused the server to spike. They were working in Keynote (after switching from Powerpoint). After they worked for about 30 minutes, I asked them to open Powerpoint. AppleFileServer barely moved. We had around 70 users logged in at the time. I also had a couple other classes log in different labs to see if we could put additional load on the server. The CPU barely hit 30 (a far cry from the 700+ that it had been hitting). I will try this with another class later on this morning to see if I can again simulate the problem.

Yesterday, we could get the server to spike with about 70 users and only 3 opening up Powerpoint. I logged in as those 3 users this morning along with the other 30+ users that had Powerpoint opened and it still had no significant impact on AppleFileServer.

Would be curious to see if the other users on this thread also have Microsoft Office 2004 and if tossing the Library (or specifically any Microsoft preferences) made a difference.

I am having the same problem, AFP CPU up over %200, how is that even possible!!! This is causing the server to crash 10 minutes after every restart. I need HELP fast, I am forcing all users to work from there desktops in the meantime. Here is my system log:

Server = Xserve Dual 1.33GHz PowerPC G4 running 10.5.5 w/2GBs RAM w/Xserve RAID (DAS)

Jan 9 12:29:26 localhost kernel[0]: Darwin Kernel Version 9.5.0: Wed Sep 3 11:31:44 PDT 2008; root:xnu-1228.7.58~1/RELEASE_PPC
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12300 allow tcp from any to any established
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12301 allow tcp from any to any out
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12302 allow tcp from any to any dst-port 22
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12302 allow udp from any to any dst-port 22
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12303 allow udp from any to any out keep-state
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12304 allow tcp from any to any dst-port 53 out keep-state
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12304 allow udp from any to any dst-port 53 out keep-state
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12305 allow udp from any to any in frag
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12306 allow tcp from any to any dst-port 311
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12307 allow tcp from any to any dst-port 625
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12308 allow udp from any to any dst-port 626
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12309 allow icmp from any to any icmptypes 8
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12310 allow icmp from any to any icmptypes 0
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 12311 allow igmp from any to any
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 01000 allow ip from any to any via lo0
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 01010 deny ip from any to 127.0.0.0/8
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 01020 deny ip from 224.0.0.0/4 to any in
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 01030 deny tcp from any to 224.0.0.0/4 in
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 65534 deny ip from any to any
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: net.inet.ip.fw.enable: 1 -> 0
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 00001 allow
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: udp from any to any 626
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 01000 allow
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: ipv6 from any to any via lo0
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 01100 allow
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: ipv6 from any to
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: ff02::/16
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: 65000 deny
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: ipv6 from any to any
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: net.inet6.ip6.fw.enable: 1 -> 0
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: net.inet.tcp.delayed_ack: 3 -> 2
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: /etc/rc.server: line 55: logger: command not found
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: kern.maxproc: 532 -> 2500
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: kern.ipc.somaxconn: 128 -> 2500
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: kern.maxvnodes: 33792 -> 90000
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: kern.maxprocperuid: 266 -> 1000
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: launch_msg(): Socket is not connected
Jan 9 12:29:22 localhost com.apple.launchctl.System[2]: Bug: launchctl.c:1414 (23642):9: fwexec(rcserver_tool, true) != -1
Jan 9 12:29:26 localhost com.apple.launchctl.System[2]: launchctl: Please convert the following to launchd: /etc/mach_init.d/chum.plist
Jan 9 12:29:26 localhost com.apple.launchctl.System[2]: launchctl: Please convert the following to launchd: /etc/mach_init.d/dashboardadvisoryd.plist
Jan 9 12:29:26 localhost com.apple.launchctl.System[2]: launchctl: Please convert the following to launchd: /etc/mach_init.d/pilotfish.plist
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key for string: cccTaskName
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key: cccTaskName
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key for dictionary: cccTimingDict
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown value type '5' for key: cccNextFireDate
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key for string: cccTaskUUID
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key: cccTaskUUID
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key: ServiceDescription
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key for boolean: cccRunImmediatelyOnLoad
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key for dictionary: cccTaskDict
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.bombich.ccc.scheduledtask.4719115F-5A17-4278-A4B0-1B5B8BE16385): Unknown key for integer: cccVersion
Jan 9 12:29:26 localhost com.apple.launchd[1] (com.apple.distccdConfigd): Unknown key: SHAuthorizationRight
Jan 9 12:29:26 localhost com.apple.launchd[1] (org.apache.httpd): Unknown key: SHAuthorizationRight
Jan 9 12:29:26 localhost com.apple.launchd[1] (org.cups.cupsd): Unknown key: SHAuthorizationRight
Jan 9 12:29:26 localhost com.apple.launchd[1] (org.ntp.ntpd): Unknown key: SHAuthorizationRight
Jan 9 12:29:26 localhost DirectoryService[25]: Launched version 5.5 (v514.23)
Jan 9 12:29:27 localhost kernel[0]: standard timeslicing quantum is 10000 us
Jan 9 12:29:26 localhost DirectoryService[25]: Improper shutdown detected
Jan 9 12:29:27 localhost kernel[0]: vm pagebootstrap: 511059 free pages and 13229 wired pages
Jan 9 12:29:27 localhost kernel[0]: mig table_maxdispl = 79
Jan 9 12:29:27 localhost kernel[0]: 91 prelinked modules
Jan 9 12:29:27 localhost kernel[0]: Loading security extension com.apple.security.TMSafetyNet
Jan 9 12:29:27 localhost kernel[0]: calling mpo policyinit for TMSafetyNet
Jan 9 12:29:27 localhost kernel[0]: Security policy loaded: Safety net for Time Machine (TMSafetyNet)
Jan 9 12:29:27 localhost kernel[0]: Loading security extension com.apple.nke.applicationfirewall
Jan 9 12:29:27 localhost kernel[0]: Loading security extension com.apple.security.seatbelt
Jan 9 12:29:27 localhost kernel[0]: calling mpo policyinit for mb
Jan 9 12:29:27 localhost kernel[0]: Seatbelt MACF policy initialized
Jan 9 12:29:27 localhost kernel[0]: Security policy loaded: Seatbelt Policy (mb)
Jan 9 12:29:27 localhost kernel[0]: Copyright (c) 1982, 1986, 1989, 1991, 1993
Jan 9 12:29:27 localhost kernel[0]: The Regents of the University of California. All rights reserved.
Jan 9 12:29:28 localhost kernel[0]: MAC Framework successfully initialized
Jan 9 12:29:28 localhost kernel[0]: using 10485 buffer headers and 4096 cluster IO buffer headers
Jan 9 12:29:28 localhost kernel[0]: FireWire (OHCI) Apple ID 31 built-in now active, GUID 000a95fffee499d4; max speed s800.
Jan 9 12:29:28 localhost kernel[0]: Waiting for AppleKeyswitch ...
Jan 9 12:29:27 localhost kextd[24]: 403 cached, 0 uncached personalities to catalog
Jan 9 12:29:28 localhost kernel[0]: AppleKiwiATA: PIO Mode 3 UDMA mode 6
Jan 9 12:29:28 localhost kernel[0]: AppleKiwiATA: PIO Mode 3 UDMA mode 5
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 10 (Event Change) for SCSI Domain = 0
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 10 (Event Change) for SCSI Domain = 1
Jan 9 12:29:28 localhost kernel[0]: mbinit: done
Jan 9 12:29:28 localhost kernel[0]: Security auditing service present
Jan 9 12:29:28 localhost kernel[0]: BSM auditing present
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 7 (Link Status Change) for SCSI Domain = 0
Jan 9 12:29:28 localhost kernel[0]: FusionFC: Link is down for SCSI Domain = 0.
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 5 (External Bus Reset) for SCSI Domain = 0
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: External Bus Reset for SCSI Domain = 0
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 7 (Link Status Change) for SCSI Domain = 1
Jan 9 12:29:28 localhost kernel[0]: FusionFC: Link is down for SCSI Domain = 1.
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 5 (External Bus Reset) for SCSI Domain = 1
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: External Bus Reset for SCSI Domain = 1
Jan 9 12:29:28 localhost kernel[0]: rooting via boot-uuid from /chosen: D4490660-302D-36C5-850F-8991586B80DE
Jan 9 12:29:28 localhost kernel[0]: Waiting on <dict ID="0"><key>IOProviderClass</key><string ID="1">IOResources</string><key>IOResourceMatch</key><string ID="2">boot-uuid-media</string></dict>
Jan 9 12:29:28 localhost kernel[0]: Got boot device = IOService:/MacRISC2PE/pci@f2000000/AppleMacRiscPCI/AppleKiwi@1B/AppleKiwiRoot/a ta-6@0/AppleKiwiATA/ATADeviceNub@0/AppleATADiskDriver/IOATABlockStorageDevice/IO BlockStorageDriver/IBM-IC35L180AVV207-1 IBM-IC35L180AVV207-1/IOApplePartitionScheme/Apple HFS_Untitled1@3
Jan 9 12:29:28 localhost kernel[0]: BSD root: disk1s3, major 14, minor 12
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 8 (Loop State Change) for SCSI Domain = 0
Jan 9 12:29:28 localhost kernel[0]: FusionFC: Loop Initialization Packet for SCSI Domain = 0, fLIPCount = 0.
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 8 (Loop State Change) for SCSI Domain = 1
Jan 9 12:29:28 localhost kernel[0]: FusionFC: Loop Initialization Packet for SCSI Domain = 1, fLIPCount = 0.
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 7 (Link Status Change) for SCSI Domain = 0
Jan 9 12:29:28 localhost kernel[0]: FusionFC: Link is active for SCSI Domain = 0.
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 6 (Rescan) for SCSI Domain = 0
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 7 (Link Status Change) for SCSI Domain = 1
Jan 9 12:29:28 localhost kernel[0]: FusionFC: Link is active for SCSI Domain = 1.
Jan 9 12:29:28 localhost kernel[0]: FusionMPT: Notification = 6 (Rescan) for SCSI Domain = 1
Jan 9 12:29:28 localhost kernel[0]: IPv6 packet filtering initialized, default to accept, logging disabled
Jan 9 12:29:28 localhost kernel[0]: HFS: Removed 4 orphaned unlinked files or directories
Jan 9 12:29:28 localhost kernel[0]: Jettisoning kernel linker.
Jan 9 12:29:28 localhost kernel[0]: Resetting IOCatalogue.
Jan 9 12:29:28 localhost kernel[0]: UniNEnet: Ethernet address 00:0a:95:e4:99:d4
Jan 9 12:29:28 localhost kernel[0]: BCM5701Enet: Ethernet address 00:03:93:f4:e4:2a
Jan 9 12:29:28 localhost kernel[0]: Matching service count = 0
Jan 9 12:29:28 localhost kernel[0]: Matching service count = 2
Jan 9 12:29:28: --- last message repeated 4 times ---
Jan 9 12:29:28 localhost kernel[0]: AppleRS232Serial: 3b01c020 80013020 chip base, virtual, physical
Jan 9 12:29:28 localhost kernel[0]: rtclock timebase_callback: late old 1000000000 / 41534326 new 1000000000 / 41534237
Jan 9 12:29:35 localhost mDNSResponder mDNSResponder-176.2 (Aug 15 2008 14:58:56)[30]: starting
Jan 9 12:29:37 localhost kextd[24]: writing kernel link data to /var/run/mach.sym
Jan 9 12:29:39 localhost kernel[0]: UniNEnet::monitorLinkStatus - Link is up at 1000 Mbps - Full Duplex (PHY regs 5,6:0xc5e1,0x000d)
Jan 9 12:29:39 localhost mDNSResponder[30]: WARNING: sandbox_init error Could not set Mach lookup policy for service com.apple.bsd.dirhelper err=1100Could not set Mach lookup policy for service com.apple.distributed_notifications.2 err=1100Could not set Mach lookup policy for service com.apple.ocspd err=1100Could not set Mach lookup policy for service com.apple.mDNSResponderHelper err=1100Could not set Mach lookup policy for service com.apple.SecurityServer err=1100Could not set Mach lookup policy for service com.apple.SystemConfiguration.configd er
Jan 9 12:29:39 localhost com.apple.launchd[1] (com.openssh.sshd): Unknown key: SHAuthorizationRight
Jan 9 12:29:40 localhost watchdogtimerd[41]: Automatic reboot timer enabled.
Jan 9 12:29:40 localhost rpc.statd[45]: statd.notify - no notifications needed
Jan 9 12:29:40 localhost fseventsd[56]: event logs in /.fseventsd out of sync with volume. destroying old logs. (1814 19 2480)
Jan 9 12:29:40 localhost fseventsd[56]: log dir: /.fseventsd getting new uuid: 263C8649-C172-468D-A262-FD15F09D2EE9
Jan 9 12:29:40 localhost com.apple.HeadlessStartup[55]: 65:6e:30:00:0a:95
Jan 9 12:29:40 localhost bootlog[65]: BOOT_TIME: 1231522161 0
Jan 9 12:29:40 localhost com.apple.launchd[1] (com.apple.distccdConfigd[61]): Exited with exit code: 255
Jan 9 12:29:40 localhost /System/Library/CoreServices/loginwindow.app/Contents/MacOS/loginwindow[50]: Login Window Application Started
Jan 9 12:29:40 localhost emond[58]: SetUpLogs: uid = 0 gid = 0
Jan 9 12:29:40 localhost emond[58]: SetUpLogs: opening /Library/Logs/EventMonitor/EventMonitor.error.log
Jan 9 12:29:40 localhost org.apache.httpd[39]: httpd: Could not reliably determine the server's fully qualified domain name, using ::1 for ServerName
Jan 9 12:29:41 myserver kernel[0]: UniNEnet::monitorLinkStatus - Link is up at 100 Mbps - Full Duplex (PHY regs 5,6:0xc5e1,0x000d)
Jan 9 12:29:40 myserver configd[28]: setting hostname to "myserver.mydomain.com"
Jan 9 12:29:42 myserver kernel[0]: jnl: disk2s3: replay_journal: from: 81883136 to: 84717568 (joffset 0x5755000)
Jan 9 12:29:42 myserver fseventsd[56]: event logs in /Volumes/Server HD Backup/.fseventsd out of sync with volume. destroying old logs. (520 0 2479)
Jan 9 12:29:42 myserver kernel[0]: jnl: disk3s3: replay_journal: from: 50655232 to: 54996992 (joffset 0x5755000)
Jan 9 12:29:42 myserver kernel[0]: jnl: disk0s10: replay_journal: from: 7776256 to: 179712 (joffset 0x624000)
Jan 9 12:29:42 myserver fseventsd[56]: log dir: /Volumes/Server HD Backup/.fseventsd getting new uuid: BC1A3029-EDCF-4B63-8BFC-AC57C6F61CCD
Jan 9 12:29:42 myserver kernel[0]: jnl: disk0s10: journal replay done.
Jan 9 12:29:43 myserver kernel[0]: jnl: disk2s3: journal replay done.
Jan 9 12:29:43 myserver fseventsd[56]: event logs in /Volumes/XRaid SetB/.fseventsd out of sync with volume. destroying old logs. (926 1 2479)
Jan 9 12:29:43 myserver kernel[0]: serialnumberd 108 FS WRITEDATA SBF /dev/dtracehelper 13 (seatbelt)
Jan 9 12:29:43 myserver fseventsd[56]: log dir: /Volumes/XRaid SetB/.fseventsd getting new uuid: 6F8C2C81-83A3-406A-BCFC-9BC0C251DD5F
Jan 9 12:29:44 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /dev/autofs_nowait 13 (seatbelt)
Jan 9 12:29:44 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /usr/sbin 13 (seatbelt)
Jan 9 12:29:44 myserver kernel[0]: jnl: disk3s3: journal replay done.
Jan 9 12:29:44 myserver fseventsd[56]: event logs in /Volumes/XRaid SetA/.fseventsd out of sync with volume. destroying old logs. (899 2 2479)
Jan 9 12:29:44 myserver fseventsd[56]: log dir: /Volumes/XRaid SetA/.fseventsd getting new uuid: 34E79AFE-C49E-4636-8E79-322E2A115DFF
Jan 9 12:29:47 myserver ARDAgent [113]: ******ARDAgent Launched ******
Jan 9 12:29:47 myserver loginwindow[50]: Login Window Started Security Agent
Jan 9 12:29:48 myserver ARDAgent [113]: ServerNotificationReplyHandler: serverEntryRef is NULL
Jan 9 12:29:48 myserver ARDAgent [113]: ******ARDAgent Ready ******
Jan 9 12:29:49 myserver com.apple.KerberosAutoConfig[123]: Kerberos configuration is up to date
Jan 9 12:29:49 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:29:49: --- last message repeated 1 time ---
Jan 9 12:29:49 myserver servermgrd[46]: servermgr_calendar: created default calendar virtual host
Jan 9 12:29:49 myserver servermgrd[46]: servermgr_ipfilter:ipfw config:Notice:Flushed IPv4 rules
Jan 9 12:29:49 myserver servermgrd[46]: servermgr_ipfilter:ipfw config:Notice:Flushed IPv6 rules
Jan 9 12:29:49 myserver authorizationhost[117]: MechanismInvoke 0x11ebf0 retainCount 2
Jan 9 12:29:49 myserver SecurityAgent[119]: MechanismInvoke 0x101620 retainCount 1
Jan 9 12:29:50 myserver SecurityAgent[119]: MechanismDestroy 0x101620 retainCount 1
Jan 9 12:29:50 myserver loginwindow[50]: Login Window - Returned from Security Agent
Jan 9 12:29:50 myserver authorizationhost[117]: MechanismDestroy 0x11ebf0 retainCount 2
Jan 9 12:29:50 myserver loginwindow[50]: USER_PROCESS: 50 console
Jan 9 12:29:50 myserver com.apple.launchd[1] (com.apple.UserEventAgent-LoginWindow[114]): Exited: Terminated
Jan 9 12:29:50 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:29:50: --- last message repeated 1 time ---
Jan 9 12:29:50 myserver com.apple.KerberosAutoConfig[145]: Kerberos configuration is up to date
Jan 9 12:29:50 myserver ARDAgent [141]: ******ARDAgent Launched ******
Jan 9 12:29:50 myserver mDNSResponder[30]: Client application registered 2 identical instances of service myserver. net-assistant.udp.local. port 3283.
Jan 9 12:29:50 myserver ARDAgent [113]: ServerNotificationReplyHandler: serverEntryRef is NULL
Jan 9 12:29:50 myserver ARDAgent [141]: _RegisterApplication(), FAILED TO REGISTER PROCESS WITH CPS/CoreGraphics in WindowServer, err=-50
Jan 9 12:29:50 myserver ARDAgent[141]: * CFMessagePort: bootstrap_register(): failed 1103 (0x44f) 'Service name already exists', port = 0x5e03, name = 'WakeUpProcessPort'\nSee /usr/include/servers/bootstrap_defs.h for the error codes.
Jan 9 12:29:50 myserver com.apple.RemoteDesktop.agent[141]: _RegisterApplication(), FAILED TO REGISTER PROCESS WITH CPS/CoreGraphics in WindowServer, err=-50
Jan 9 12:29:50 myserver ARDAgent [141]: ******ARDAgent Ready ******
Jan 9 12:29:50 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:29:52: --- last message repeated 5 times ---
Jan 9 12:29:52 myserver /System/Library/CoreServices/coreservicesd[78]: SFLSharePointsEntry::CreateDSRecord: dsCreateRecordAndOpen(Departments_Archive) returned -14135
Jan 9 12:29:52 myserver /System/Library/CoreServices/coreservicesd[78]: SFLSharePointsEntry::CreateDSRecord: dsCreateRecordAndOpen(Departments) returned -14135
Jan 9 12:29:52 myserver /System/Library/CoreServices/coreservicesd[78]: SFLSharePointsEntry::CreateDSRecord: dsCreateRecordAndOpen(Documents) returned -14135
Jan 9 12:29:53 myserver ARDAgent [141]: Exiting because bind error is not EADDRINUSE.
Jan 9 12:29:53 myserver com.apple.launchd[132] (com.apple.RemoteDesktop.agent[141]): Stray process with PGID equal to this dead job: PID 148 PPID 1 AppleVNCServer
Jan 9 12:29:53 myserver com.apple.launchd[132] (com.apple.RemoteDesktop.agent): Throttling respawn: Will start in 7 seconds
Jan 9 12:29:53 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:29:53: --- last message repeated 1 time ---
Jan 9 12:29:53 myserver com.apple.SNServer[108]: serialnumberd: recvfrom: Resource temporarily unavailable
Jan 9 12:29:54 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:29:56: --- last message repeated 3 times ---
Jan 9 12:29:56 myserver mds[49]: (Error) Server: Peer checkin failed -- no store for path '/Volumes/XRaid SetA/Departments'
Jan 9 12:29:56 myserver com.apple.AppleFileServer[107]: MDSChannelPeerCreate: (os/kern) invalid argument
Jan 9 12:30:00 myserver ARDAgent [177]: ******ARDAgent Launched ******
Jan 9 12:30:00 myserver ARDAgent [177]: ServerNotificationReplyHandler: serverEntryRef is NULL
Jan 9 12:30:00 myserver ARDAgent [177]: ******ARDAgent Ready ******
Jan 9 12:30:00 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:30:03: --- last message repeated 1 time ---
Jan 9 12:30:03 myserver mds[49]: (Error) Server: Peer checkin failed -- no store for path '/Volumes/XRaid SetA/Departments'
Jan 9 12:30:03 myserver com.apple.AppleFileServer[107]: MDSChannelPeerCreate: (os/kern) invalid argument
Jan 9 12:30:22 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:30:28: --- last message repeated 3 times ---
Jan 9 12:30:28 myserver Disk Utility[206]: ********
Jan 9 12:30:28 myserver Disk Utility[206]: Disk Utility started.
Jan 9 12:30:28 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:30:37: --- last message repeated 1 time ---
Jan 9 12:30:37 myserver Disk Utility[206]: Verifying volume “Server HD”
Jan 9 12:30:37 myserver Disk Utility[206]: Starting verification tool:
Jan 9 12:30:43 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /private/var/root/Library/Preferences/.GlobalPreferences.plist 13 (seatbelt)
Jan 9 12:30:43 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:31:30 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /Library/Preferences/.GlobalPreferences.plist 13 (seatbelt)
Jan 9 12:30:43 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:31:30 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /private/var/root/Library/Preferences/.GlobalPreferences.plist 13 (seatbelt)
Jan 9 12:30:45 myserver login[225]: USER_PROCESS: 225 ttys000
Jan 9 12:31:30 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /Library/Preferences/.GlobalPreferences.plist 13 (seatbelt)
Jan 9 12:31:29 myserver Disk Utility[206]:
Jan 9 12:31:30 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /private/var/root/Library/Preferences/.GlobalPreferences.plist 13 (seatbelt)
Jan 9 12:31:30 myserver Disk Utility[206]: Performing live verification.
Jan 9 12:31:30 myserver kernel[0]: serialnumberd 108 FS READDATA SBF /Library/Preferences/.GlobalPreferences.plist 13 (seatbelt)
Jan 9 12:31:30 myserver Disk Utility[206]: Checking Journaled HFS Plus volume.
Jan 9 12:31:30 myserver Disk Utility[206]: Checking Extents Overflow file.
Jan 9 12:31:30 myserver Disk Utility[206]: Checking Catalog file.
Jan 9 12:31:30 myserver Disk Utility[206]: Checking multi-linked files.
Jan 9 12:31:30 myserver Disk Utility[206]: Checking Catalog hierarchy.
Jan 9 12:31:30 myserver Disk Utility[206]: Checking Extended Attributes file.
Jan 9 12:31:30 myserver Disk Utility[206]: Checking volume bitmap.
Jan 9 12:31:30 myserver Disk Utility[206]: Checking volume information.
Jan 9 12:30:51 myserver mdworker[105]: (Error) SyncInfo: Boot-cache avoidance timed out!
Jan 9 12:31:30: --- last message repeated 1 time ---
Jan 9 12:31:30 myserver Disk Utility[206]: The volume Server HD appears to be OK.
Jan 9 12:31:30 myserver Disk Utility[206]: Verifying tool completed:
Jan 9 12:31:30 myserver Disk Utility[206]:
Jan 9 12:31:35: --- last message repeated 1 time ---
Jan 9 12:31:35 myserver mds[49]: (Error) Server: Peer checkin failed -- no store for path '/Volumes/XRaid SetA/Departments'
Jan 9 12:31:35 myserver com.apple.AppleFileServer[107]: MDSChannelPeerCreate: (os/kern) invalid argument
Jan 9 12:31:40 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:32:10: --- last message repeated 5 times ---
Jan 9 12:33:53 myserver com.apple.launchd[1] (0x100f80.mdworker[242]): Exited: Killed
Jan 9 12:36:10 myserver AppleVNCServer[178]: CGSCreateKeyboardEvent is obsolete; please use CGSCreateKeyboardEventOfLength
Jan 9 12:36:10 myserver com.apple.RemoteDesktop.agent[177]: Fri Jan 9 12:36:10 myserver.mydomain.com AppleVNCServer[178] <Warning>: CGSCreateKeyboardEvent is obsolete; please use CGSCreateKeyboardEventOfLength
Jan 9 12:37:24 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:38:14: --- last message repeated 5 times ---
Jan 9 12:38:14 myserver com.apple.coreservicesd[78]: NOTE: Using non-mach-based version of client -> server communication, via direct function calls.
Jan 9 12:38:26: --- last message repeated 5 times ---
Jan 9 12:38:26 myserver SyncServer[306]: SyncServer: Reaping records for inactive clients. Next reap on 2009-02-23 12:38:26 -0500
Jan 9 12:38:26 myserver SyncServer[306]: SyncServer: Truth vacuumed. Next vacuum date 2009-01-23 12:38:26 -0500

Real similar setup to ours. We have one home directory server for faculty one for students. Each using one side of an xraid. If you look at your xraid settings using Raid Admin under performance do you have the "Allow Host Cache Flushing" checked or unchecked? We have it unchecked. This setting made a major difference.

ok, most of us can't work anymore with 10.5.x and AFP service and serverbased userfolders, because AFP service is using complete CPU, up to 700% (8-Core Xeon). we all know, apple has no solution, we have no solution, nobody can really help.

so, what's next? where is apple and why Apple don't want to help us, maybe they can't, because the don't know why their own essential service is buggy. But, what can we do? we have to work everyday in our agencies, universities, schools etc. But OSX Server 10.5.x is so buggy at this time, that it is unusable in networks with more than 30 serverbased users.

any ideas? should we make this public on websites, magazines, newsgroups..etc.

we need a solution, we need help, we need Apple's atttention - now !?

Our Xserve has been running really well for all of last year, typical AppleFileServer load is 20%, all of a sudden this year I have seen the same problem you guys are seeing, AppleFileServer jumping to 180% and not settling back down. Instead of restarting the server and getting everyone to log out, I have just been putting all users to sleep and killing the AppleFileServer process, which is much quicker than restarting.

I've just run cocktail and diskwarrior on the server and xserve RAID and we have just had two days with the CPU averaging at 30%, I'm not saying its fixed yet.

I also noticed some users spotlight was re-indexing on every log in, so I've trashed their .Spotlight-V100 folder and let it create a fresh index

I've also installed Shark for apple's CHUD tools so next time it happens I can run a system trace. If everyone else does that maybe we can compare results and see if there is a common cause.