SSLVPN connection on MAC OS 10.6 pegging java CPU processing at 100% utilisation

  • 7008072
  • 07-Mar-2011
  • 26-Apr-2012

Environment

Novell Access Manager 3.1 SSLVPN Server
Novell Access Manager 3.1 Support Pack 3 applied

Situation

SSLVPN Enterprise mode client running Mac OS 10.6. After successfully connecting with the Safari 
browser, users get 100% utilisation on the java process for a long period of time (up to 10 mins
on occasions). Manually killing this java process seems to allow the connection to continue
without issues.

Could not duplicate issue on all machines running same OS and browser.

Resolution

Purge cache on the browser and reconnect.

Additional Information

Looking at the log files that were requested from a problem host, one could determine that the java process in use when the issue was occuring was the copyfile thread. When the SSLVPN client connects to the server, we try and backup all the temp cache files, cookies, etc when running in sandbox mode. In the above scenario, the cache file was large and the file copy process was taking up resources for a longer period of time. A defect has been opened to address this issue.

Following is a copy of the key files and stack dump for reference:

Here's the logs and the stack trace ...

mswmbp42:com.apple.Safari matt$ ls -alh
total 371544
drwxr-xr-x@ 7 matt staff 238B Mar 4 10:12 .
drwxr-xr-x 94 matt staff 3.1K Mar 1 13:11 ..
-rw-r--r--@ 1 matt staff 8.0M Mar 4 10:12 .Cache.db_novl
-rw-r--r--@ 1 matt staff 6.0K Jan 31 13:23 .DS_Store
-rw-r--r--@ 1 matt staff 173M Mar 4 10:11 Cache.db
drwx------@ 2 matt staff 68B Dec 16 23:46 Extensions
drwx------@ 2868 matt staff 95K Mar 4 10:11 Webpage Previews




mswmbp42:History matt$ ls -alh
total 592
drwxr-xr-x@ 32 matt staff 1.1K Mar 4 10:11 .
drwxr-xr-x@ 4 matt staff 136B Jan 31 13:19 ..
-rw-r--r--@ 1 matt staff 2.5K Mar 4 10:11 .tracked filenames.plist
-rw-r--r-- 1 matt staff 4.7K Mar 4 09:02 Safari history item-1.webhistory
-rw-r--r-- 1 matt staff 4.7K Mar 4 09:03 Safari history item-2.webhistory
-rw-r--r-- 1 matt staff 4.7K Mar 4 09:03 Safari history item-3.webhistory
-rw-r--r-- 1 matt staff 10K Mar 4 09:04 Safari history item-4.webhistory
-rw-r--r-- 1 matt staff 15K Mar 4 09:06 Safari history item-5.webhistory
-rw-r--r-- 1 matt staff 13K Mar 4 09:06 Safari history item-6.webhistory
-rw-r--r-- 1 matt staff 12K Mar 4 09:26 Safari history item-7.webhistory
-rw-r--r-- 1 matt staff 14K Mar 4 09:01 Safari history item.webhistory
-rw-r--r-- 1 matt staff 38K Mar 4 08:53
http:%2F%2Feurope.wsj.com%2Farticle%2FSB10001424052748703580004576179792275553856.html.webhistory
-rw-r--r-- 1 matt staff 19K Mar 4 09:08
http:%2F%2Ffeeds.appleinsider.com%2Fclick.phdo?i=d006f1231c31ae1f0ba0d909eee62120.webhistory
-rw-r--r-- 1 matt staff 4.2K Mar 4 09:09
http:%2F%2Fh10010.www1.hp.com%2Fwwpc%2Fus%2Fen%2Fsm%2FWF06b%2F12169-304608-336885-336885-336885-3662826-3741529-3741530.html?jumpid=reg_R1002_USEN.webhistory
-rw-r--r-- 1 matt staff 221B Mar 4 08:53
http:%2F%2Fonline.wsj.com%2Farticle%2FSB10001424052748703580004576179792275553856.html.webhistory
-rw-r--r-- 1 matt staff 288B Mar 4 09:08
http:%2F%2Fwww.appleinsider.com%2Farticles%2F11%2F03%2F04%2Fchina_mobile_exec_apple_interested_in_building_4g_lte_iphone_at_an_early_date.html.webhistory
-rw-r--r-- 1 matt staff 2.9K Mar 4 10:11
http:%2F%2Fwww.google.com%2Fig.webhistory
-rw-r--r-- 1 matt staff 6.2K Mar 4 09:01
http:%2F%2Fwww.google.com%2Fsearch?source=ig&hl=en&rlz=&q=vmware+hcl&aq=f&aqi=g8g-s1g1&aql=&oq=.webhistory
-rw-r--r-- 1 matt staff 121B Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation%2F.webhistory
-rw-r--r-- 1 matt staff 180B Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation%2Fnovellaccessmanager31%2F.webhistory
-rw-r--r-- 1 matt staff 5.4K Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation%2Fnovellaccessmanager31%2Findex.html.webhistory
-rw-r--r-- 1 matt staff 334B Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation%2Fnovellaccessmanager31%2Fsslvpnclienthelp%2F?page=%2Fdocumentation%2Fnovellaccessmanager31%2Fsslvpnclienthelp%2Fdata%2Fbookinfo.html.webhistory
-rw-r--r-- 1 matt staff 239B Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation%2Fnovellaccessmanager31%2Fsslvpnclienthelp%2Fdata%2Fba9j4uq.html.webhistory
-rw-r--r-- 1 matt staff 247B Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation%2Fnovellaccessmanager31%2Fsslvpnclienthelp%2Fdata%2Fbdjlqsl.html.webhistory
-rw-r--r-- 1 matt staff 4.2K Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation%2Fnovellaccessmanager31%2Fsslvpnclienthelp%2Fdata%2Fbookinfo.html.webhistory
-rw-r--r-- 1 matt staff 13K Mar 4 09:11
http:%2F%2Fwww.novell.com%2Fdocumentation.webhistory
-rw-r--r-- 1 matt staff 4.3K Mar 4 09:01
http:%2F%2Fwww.vmware.com%2Fgo%2Fhcl.webhistory
-rw-r--r-- 1 matt staff 28K Mar 4 09:04
http:%2F%2Fwww.vmware.com%2Fresources%2Fcompatibility%2Fsearch.php?action=search&deviceCategory=san&productId=1&advancedORbasic=advanced&maxDisplayRows=50&key=HP&datePosted=-1&partnerId%255B%255D=-1&isSVA=0&rorre=0.webhistory
-rw-r--r-- 1 matt staff 240B Mar 4 09:01
http:%2F%2Fwww.vmware.com%2Fresources%2Fcompatibility%2Fsearch.php?hl=en&rlz=&q=vmware%2520hcl&aq=f&aqi=g8g-s1g1&aql=&oq=.webhistory
-rw-r--r-- 1 matt staff 135B Mar 4 10:11
https:%2F%2Fidp.hfcc.edu%2Fnidp%2Fidff%2Fsso?id=MyHFCC&sid=0&option=credential&sid=0.webhistory
-rw-r--r-- 1 matt staff 117B Mar 4 10:11
https:%2F%2Fidp.hfcc.edu%2Fnidp%2Fidff%2Fsso?sid=0.webhistory
-rw-r--r-- 1 matt staff 94B Mar 4 10:11
https:%2F%2Fvpn.hfcc.edu%2Fsslvpn%2Flogin.webhistory






swmbp42:Safari matt$ ls -alh
total 26480
drwxr-xr-x@ 19 matt staff 646B Mar 4 10:12 .
drwx------ 43 matt staff 1.4K Oct 25 17:19 ..
-rw-r--r--@ 1 matt staff 9.8K Mar 4 10:12 .Downloads.plist_novl
-rw-r--r--@ 1 matt staff 69K Mar 4 10:12 .Form Values_novl
-rw-r--r--@ 1 matt staff 494K Mar 4 10:12 .History.plist_novl
-rw-r--r--@ 1 matt staff 676B Mar 4 10:12 .LastSession.plist_novl
-rw-r--r--@ 1 matt staff 53K Feb 28 20:50 Bookmarks.plist
-rw-r--r--@ 1 matt staff 11K Feb 27 16:28 Configurations.plist.signed
drwx------@ 5 matt staff 170B Feb 17 10:44 Databases
-rw-r--r--@ 1 matt staff 9.8K Mar 4 08:25 Downloads.plist
drwx------@ 3 matt staff 102B Feb 18 14:49 Extensions
-rw-r--r--@ 1 matt staff 69K Mar 4 09:06 Form Values
-rw-r--r--@ 1 matt staff 494K Mar 4 10:11 History.plist
-rw-------@ 1 matt staff 5.8M Mar 4 10:11 HistoryIndex.sk
-rw-r--r--@ 1 matt staff 676B Mar 4 10:11 LastSession.plist
drwx------@ 217 matt staff 7.2K Mar 3 13:11 LocalStorage
-rw-r--r--@ 1 matt staff 7.7K Aug 30 2010 SearchProviders.plist.signed
-rw-r--r--@ 1 matt staff 1.2K Mar 3 20:50 TopSites.plist
-rw-r--r--@ 1 matt staff 5.9M Mar 4 09:26 WebpageIcons.db




mswmbp42:Keychains matt$ ls -alh
total 2880
drwx------ 10 matt staff 340B Mar 4 10:12 .
drwx------ 43 matt staff 1.4K Oct 25 17:19 ..
-rw-------@ 1 matt staff 6.0K Feb 27 15:23 .DS_Store
-r--r--r-- 1 matt staff 0B Jul 31 2010 .fl62323D2F
-r--r--r-- 1 matt staff 0B Aug 1 2010 .flA6A9AF81
-rw-r--r--@ 1 matt staff 627K Mar 4 10:12 .login.keychain_novl
drwx------ 2 matt staff 68B Oct 25 17:48 .syncinfo
-rw-r--r-- 1 matt staff 20K Aug 1 2010
Microsoft_Intermediate_Certificates
-rw-r--r-- 1 matt staff 627K Mar 4 08:25 login.keychain
-rw-r--r-- 1 matt staff 154K Feb 26 00:58 login_renamed.keychain




mswmbp42:Cookies matt$ ls -alh
total 2056
drwxr-xr-x 5 matt staff 170B Mar 4 10:17 .
drwx------ 43 matt staff 1.4K Oct 25 17:19 ..
-rw-r--r--@ 1 matt staff 511K Mar 4 10:12 .Cookies.plist_novl
-rw-r--r--@ 1 matt staff 511K Mar 4 10:17 Cookies.plist
-rw-r--r-- 1 matt staff 1.9K Mar 1 11:42 com.apple.appstore.plist








mswmbp42:~ matt$ ps -ef | grep java
501 24275 23846 0 5:19.39 ?? 6:37.52 /usr/bin/java -jar
/Users/matt/client-cleanup.jar -r 62200 Safari False
501 24406 24038 0 0:00.00 ttys000 0:00.00 grep java
mswmbp42:~ matt$ jstack 24275
2011-03-04 10:18:42
Full thread dump Java HotSpot(TM) 64-Bit Server VM (17.1-b03-307 mixed mode):


"Attach Listener" daemon prio=9 tid=102912000 nid=0x119a01000 waiting on
condition [00000000]
java.lang.Thread.State: RUNNABLE


"Low Memory Detector" daemon prio=5 tid=101829800 nid=0x11960a000 runnable
[00000000]
java.lang.Thread.State: RUNNABLE


"CompilerThread1" daemon prio=9 tid=101828800 nid=0x119507000 waiting on
condition [00000000]
java.lang.Thread.State: RUNNABLE


"CompilerThread0" daemon prio=9 tid=101828000 nid=0x119404000 waiting on
condition [00000000]
java.lang.Thread.State: RUNNABLE


"Signal Dispatcher" daemon prio=9 tid=101827000 nid=0x119301000 runnable
[00000000]
java.lang.Thread.State: RUNNABLE


"Surrogate Locker Thread (CMS)" daemon prio=5 tid=11801a800 nid=0x117704000
waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE


"Finalizer" daemon prio=8 tid=101815800 nid=0x117601000 in Object.wait()
[117600000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <1068111f0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <1068111f0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)


"Reference Handler" daemon prio=10 tid=101814800 nid=0x117304000 in
Object.wait() [117303000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106811050> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <106811050> (a java.lang.ref.Reference$Lock)


"main" prio=5 tid=102801000 nid=0x100501000 runnable [100500000]
java.lang.Thread.State: RUNNABLE
at java.io.FileInputStream.read(Native Method)
at
com.novell.accessmanager.sslvpn.desktop_cleanup.ClientClear.copyFile(ClientClear.java:900)
at
com.novell.accessmanager.sslvpn.desktop_cleanup.ClientClear.copyFile(ClientClear.java:884)
at
com.novell.accessmanager.sslvpn.desktop_cleanup.ClientClear.InitClean(ClientClear.java:748)
at
com.novell.accessmanager.sslvpn.desktop_cleanup.ClientClear.InitwithApplet(ClientClear.java:333)
at
com.novell.accessmanager.sslvpn.desktop_cleanup.ClientClear.main(ClientClear.java:1426)


"VM Thread" prio=9 tid=118012000 nid=0x117201000 runnable


"Gang worker#0 (Parallel GC Threads)" prio=9 tid=102802800 nid=0x102301000
runnable


"Gang worker#1 (Parallel GC Threads)" prio=9 tid=102803000 nid=0x102404000
runnable


"Gang worker#2 (Parallel GC Threads)" prio=9 tid=102803800 nid=0x102507000
runnable


"Gang worker#3 (Parallel GC Threads)" prio=9 tid=102804000 nid=0x10260a000
runnable


"Concurrent Mark-Sweep GC Thread" prio=9 tid=10287f800 nid=0x116d07000 runnable
"VM Periodic Task Thread" prio=10 tid=10183b000 nid=0x11970d000 waiting on
condition


"Exception Catcher Thread" prio=10 tid=102801800 nid=0x10173b000 runnable
JNI global references: 918