{"action":"created","issue":{"url":"https://api.github.com/repos/GoogleCloudPlatform/bigdata-interop/issues/3","labels_url":"https://api.github.com/repos/GoogleCloudPlatform/bigdata-interop/issues/3/labels{/name}","comments_url":"https://api.github.com/repos/GoogleCloudPlatform/bigdata-interop/issues/3/comments","events_url":"https://api.github.com/repos/GoogleCloudPlatform/bigdata-interop/issues/3/events","html_url":"https://github.com/GoogleCloudPlatform/bigdata-interop/issues/3","id":59291032,"number":3,"title":"Issue with JobTracker freezing on later versions of gcs-connector","user":{"login":"ap0","id":1538252,"avatar_url":"https://avatars.githubusercontent.com/u/1538252?v=3","gravatar_id":"","url":"https://api.github.com/users/ap0","html_url":"https://github.com/ap0","followers_url":"https://api.github.com/users/ap0/followers","following_url":"https://api.github.com/users/ap0/following{/other_user}","gists_url":"https://api.github.com/users/ap0/gists{/gist_id}","starred_url":"https://api.github.com/users/ap0/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ap0/subscriptions","organizations_url":"https://api.github.com/users/ap0/orgs","repos_url":"https://api.github.com/users/ap0/repos","events_url":"https://api.github.com/users/ap0/events{/privacy}","received_events_url":"https://api.github.com/users/ap0/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2015-02-27T20:38:58Z","updated_at":"2015-02-27T20:57:49Z","closed_at":null,"body":"Using Hadoop 1.2.1 with the latest GCS connector (as of this writing), we run into a condition after a job completes where the job tracker completely freezes for ~15 minutes (the web UI is inaccessible and applications cannot submit new jobs to the cluster, but the machine is still accessible).  This causes a bunch of headaches with job failures/etc.  This has happened on a couple clusters in GCE (one 128 node, one 16 node; namenode is sized appropriately).  It used to happen intermittently but now it's become very frequent.\r\n\r\nI did a jstack dump when it was frozen which you can see here: https://gist.github.com/ap0/89c4fce43bfe177f15cd\r\n\r\nThe one that sticks out is this:\r\nThread 5369: (state = IN_NATIVE)\r\n - java.net.SocketOutputStream.socketWrite0(java.io.FileDescriptor, byte[], int, int) @bci=0 (Interpreted frame)\r\n - java.net.SocketOutputStream.socketWrite(byte[], int, int) @bci=52, line=113 (Interpreted frame)\r\n - java.net.SocketOutputStream.write(byte[], int, int) @bci=4, line=159 (Interpreted frame)\r\n - sun.security.ssl.OutputRecord.writeBuffer(java.io.OutputStream, byte[], int, int, int) @bci=5, line=377 (Interpreted frame)\r\n - sun.security.ssl.OutputRecord.write(java.io.OutputStream, boolean, java.io.ByteArrayOutputStream) @bci=458, line=363 (Interpreted frame)\r\n - sun.security.ssl.SSLSocketImpl.writeRecordInternal(sun.security.ssl.OutputRecord, boolean) @bci=62, line=830 (Interpreted frame)\r\n - sun.security.ssl.SSLSocketImpl.writeRecord(sun.security.ssl.OutputRecord, boolean) @bci=302, line=801 (Interpreted frame)\r\n - sun.security.ssl.AppOutputStream.write(byte[], int, int) @bci=161, line=122 (Interpreted frame)\r\n - org.apache.http.impl.io.AbstractSessionOutputBuffer.write(byte[], int, int) @bci=34, line=128 (Interpreted frame)\r\n...\r\n\r\nIt looks like it gets hung in this call.  My suspicion was that the connection dies during the transfer and there's no SO_TIMEOUT value set.  I tried changing this in the google-http-java-client by setting the SO_TIMEOUT value on SSL sockets (https://github.com/zulily/google-http-java-client/commit/380341e5119ecc03a1fbeb831f9806cd9844d182), which seemed promising but eventually did not work.  A colleague said they had issues with the job tracker locking up as well; they found the problem occurred after a job completed when it would write the log files to GCS; their fix was to just disable this log writing.\r\n\r\nOne thing that does work is to use the older version of gcs-connector which we have running on some other clusters (1.2.8).  This one does not seem to exhibit this behavior.  I think a regression occurred between then and now that is causing this, but I have been unable to track it down."},"comment":{"url":"https://api.github.com/repos/GoogleCloudPlatform/bigdata-interop/issues/comments/76470405","html_url":"https://github.com/GoogleCloudPlatform/bigdata-interop/issues/3#issuecomment-76470405","issue_url":"https://api.github.com/repos/GoogleCloudPlatform/bigdata-interop/issues/3","id":76470405,"user":{"login":"dennishuo","id":7410123,"avatar_url":"https://avatars.githubusercontent.com/u/7410123?v=3","gravatar_id":"","url":"https://api.github.com/users/dennishuo","html_url":"https://github.com/dennishuo","followers_url":"https://api.github.com/users/dennishuo/followers","following_url":"https://api.github.com/users/dennishuo/following{/other_user}","gists_url":"https://api.github.com/users/dennishuo/gists{/gist_id}","starred_url":"https://api.github.com/users/dennishuo/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dennishuo/subscriptions","organizations_url":"https://api.github.com/users/dennishuo/orgs","repos_url":"https://api.github.com/users/dennishuo/repos","events_url":"https://api.github.com/users/dennishuo/events{/privacy}","received_events_url":"https://api.github.com/users/dennishuo/received_events","type":"User","site_admin":false},"created_at":"2015-02-27T20:57:49Z","updated_at":"2015-02-27T20:57:49Z","body":"Thanks for the report! My first suspicion would be that this could be related to the \"directory modification timestamps of parent directories\" feature, originally introduced in 1.2.9:\r\n\r\n1.2.9 - 2014-09-18\r\n\r\n  1. When directory contents are updated e.g., files or directories are added,\r\n     removed, or renamed the GCS connector will now attempt to update a\r\n     metadata property on the parent directory with a modification time. The\r\n     modification time recorded will be used as the modification time in\r\n     subsequent FileSystem#getStatus(...), FileSystem#listStatus and\r\n     FileSystem#globStatus(...) calls and is the time as reported by\r\n     the system clock of the system that made the modification.\r\n\r\nSince the timestamps were really only important for some directories, we found it better to only turn on the feature for some paths:\r\n\r\n1.3.0 - 2014-10-17\r\n\r\n  1. Directory timestamp updating can now be controlled via user-settable\r\n     properties \"fs.gs.parent.timestamp.update.enable\",\r\n     \"fs.gs.parent.timestamp.update.substrings.excludes\". and\r\n     \"fs.gs.parent.timestamp.update.substrings.includes\" in core-site.xml. By\r\n     default, timestamp updating is enabled for the YARN done and intermediate\r\n     done directories and excluded for everything else. Strings listed in\r\n     includes take precedence over excludes.\r\n  2. Directory timestamp updating will now occur on a background thread inside\r\n     GoogleCloudStorageFileSystem.\r\n\r\nYou could try setting fs.gs.parent.timestamp.update.enable = false to see if it works around this issue while we try to dig into the root cause.\r\n\r\nFor reference, does this seem to get slower and slower the longer the jobtracker is running, or is it related to the size of the job? In your case, how long had the jobtracker been running, and approximately how many files did the slow jobs each process?"}}