You are viewing a plain text version of this content. The canonical link for it is here.
Posted to hdfs-user@hadoop.apache.org by Stuart Smith <st...@yahoo.com> on 2010/04/22 00:46:30 UTC
hadoop log timestamps & file timestamps not same as system time
Hello,
I've noticed an odd situation:
The timestamps in my hadoop namenode log (and filesystem) appear to be an hour behind the actual time on the system (as supplied by `date`).
I checked that this wasn't user error by stopping and starting hadoop, and checking the most recent messages (as well as the last time the file was modified).
For example, you can see the last modified time, and the timestamp on the shutdown log message different significantly:
stu@ubuntu-namenode:~/hadoop/logs$ ls -l hadoop-stu-namenode-ubuntu-namenode.log
-rw-r--r-- 1 stu stu 22148124 2010-04-21 15:33 hadoop-stu-namenode-ubuntu-namenode.log
stu@ubuntu-namenode:~/hadoop/logs$ tail -f hadoop-stu-namenode-ubuntu-namenode.log
....
2010-04-21 14:33:19,032 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: SHUTDOWN_MSG:
/************************************************************
SHUTDOWN_MSG: Shutting down NameNode at ubuntu-namenode/192.168.193.87
************************************************************/
I also checked this while hadoop was running: the messages are consistently an hour behind.
More troubling, this appears affect the filesystem timestamps as well.
stu@ubuntu-namenode:~/hadoop/bin$ date
Wed Apr 21 15:53:34 PDT 2010
stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -touchz /test
stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -ls /
Found 2 items
drwxr-xr-x - stu supergroup 0 2010-04-20 16:51 /home
-rw-r--r-- 3 stu supergroup 0 2010-04-21 14:53 /test
Interestingly, the datanodes appear to be fine:
stu@ubuntu-hadoop-2:~/hadoop/logs$ ls -l hadoop-stu-datanode-ubuntu-hadoop-2.log
-rw-r--r-- 1 stu stu 4918505 2010-04-21 15:47 hadoop-stu-datanode-ubuntu-hadoop-2.log
stu@ubuntu-hadoop-2:~/hadoop/logs$ tail -n 1 hadoop-stu-datanode-ubuntu-hadoop-2.log
2010-04-21 15:47:21,875 INFO org.mortbay.log: jetty-6.1.14
Is there something wrong here? Am I just doing something crazy/dumb?
Note that I discovered this after getting some rather odd behavior from hbase - hbase appears to work fine, except it's continually adding the regionservers onto the list so, in my itty-bitty cluster of about 4 machines + 1 namenode, the master reports back ~ 1000s of regionservers and growing.. There are indications timing issues involved in that as well, but I figure I should get hdfs working first :)
Note that I do have NTP running to keep all these boxes in sync, but the NTP server will go down for an hour or so intermittently (due to some network issues that don't involve the hadoop cluster). All the system times on the machines appear to be (at least) within a few seconds of each other.
I'm running hadoop 0.20.2
Any thoughts? Any debugging guidance? I'm pretty stumped.
Take care,
-stu
Re: hadoop log timestamps & file timestamps not same as system time [SOLVED]
Posted by Stuart Smith <st...@yahoo.com>.
Ok. Solved the timestamp issue.
The best solution I found was:
export TZ=`cat /etc/timezone`
(which I added to .bashrc)
I found it here:
http://davidwinterbourne.com/?p=37
With the common explanation that it should be symbolic link or java scans /usr/share/zoneinfo looking for a match using some weird logic.
However, I'm not entirely comfortable with this explanation:
I had two machines with the exact same configuration and the exact same files in /usr/share/zoneinfo, but with one reporting PST in java, and the other, PDT. So there could well be some other weirdness here.
Hopefully this solves the original issue (which was hbase regionservers continually being re-added to the master with a cycle of MSG_CALL_SERVER_STARTUP messages to the same machine).
Oddly, hbase seemed to work fine, it just had a huge and ever growing list of regionservers stored the master, which would seem bad long-term.
Not sure whether this (hbase) issue would go in hbase, hadoop, or java, at this point ?
Thanks for the help!
Take care,
-stu
--- On Thu, 4/22/10, Stuart Smith <st...@yahoo.com> wrote:
> From: Stuart Smith <st...@yahoo.com>
> Subject: Re: hadoop log timestamps & file timestamps not same as system time
> To: hdfs-user@hadoop.apache.org
> Date: Thursday, April 22, 2010, 3:28 PM
> Hello Eric,
>
> There's definitely an issue with timezones here
> (yes, deprecated, but to the point):
>
> import java.util.Date;
> import java.io.*;
>
> class testDateTime
> {
> public static void main(
> String[] argv )
> {
>
> Date d = new Date();
>
> System.out.println( "date: " + d.toString() );
> }
> }
>
> says:
>
> stu@ubuntu-namenode:~/testtime$ java testDateTime
> date: Thu Apr 22 11:37:32 PST 2010
> stu@ubuntu-namenode:~/testtime$ date
> Thu Apr 22 12:37:34 PDT 2010
> stu@ubuntu-namenode:~/testtime$ cat /etc/timezone
> America/Los_Angeles
>
> but then says:
>
> stu@ubuntu-hadoop-1:~/testtime$ java testDateTime
> date: Thu Apr 22 12:38:11 PDT 2010
> stu@ubuntu-hadoop-1:~/testtime$ date
> Thu Apr 22 12:38:12 PDT 2010
> stu@ubuntu-hadoop-1:~/testtime$ cat /etc/timezone
> America/Los_Angeles
>
> Still digging into what's messing up java (or what java is
> messing up - every other program seems to be getting it
> right).
> I've seen a couple posts around about localtime needing to
> be a symbolic link for java, etc, but they're all outdated,
> and not, apparently for ubuntu.
>
> I've diff'd the localtime files from both machines, and
> they're the same, so something really odd is going on here.
>
> But at least you got me heading in the right direction :)
>
> Hopefully my next post will be the one with the answer..
>
> Take care,
> -stu
>
>
>
> --- On Thu, 4/22/10, Eric Sammer <es...@cloudera.com>
> wrote:
>
> > From: Eric Sammer <es...@cloudera.com>
> > Subject: Re: hadoop log timestamps & file
> timestamps not same as system time
> > To: hdfs-user@hadoop.apache.org,
> stu24mail@yahoo.com
> > Date: Thursday, April 22, 2010, 2:00 AM
> > Java *should* use the machine's
> > configured TZ info (in whatever form
> > that manifests as on the platform in question). For
> Linux,
> > it usually
> > means /etc/localtime and / or possibly the environment
> in
> > which the
> > jvm was executed. If I recall this may be set
> explicitly
> > using some
> > magic (i.e. undocumented) property one can pass to the
> jvm.
> > As for the
> > timestamps themselves, they're generated by log4j
> within
> > the
> > appropriate logging method (.info(), warn(), ...).
> The
> > timezone
> > selected is that of the host jvm within which the app
> is
> > running.
> >
> > On Thu, Apr 22, 2010 at 1:39 AM, <st...@yahoo.com>
> > wrote:
> > > Cool thx!
> > >
> > > I already moved ntp to NN (had the same thought).
> All
> > machines sync to the same apt-mirror, but I'll check
> the TZ
> > files to make sure. Not much left to try...
> > > I even formatted NN, and it didn't go away.
> > >
> > > Next would be to dig up hadoop source for
> timestamps,
> > and run it in a harness, I guess. Could be java
> > versioning/TZ issue, I suppose (Is java tzdata
> managed
> > separately?)
> > >
> > > We'll see
> > >
> > > Best,
> > > -stu
> > > Sent from my Verizon Wireless BlackBerry
> > >
> > > -----Original Message-----
> > > From: Eric Sammer <es...@cloudera.com>
> > > Date: Thu, 22 Apr 2010 01:17:25
> > > To: <hd...@hadoop.apache.org>
> > > Subject: Re: hadoop log timestamps & file
> > timestamps not same as system time
> > >
> > > My initial inclination is to check the timezone
> of the
> > machines. An
> > > hour difference smells like DST shift. Check that
> the
> > OS are the same
> > > version / patch level (as zoneinfo files may
> have
> > changed based on
> > > legislation recently passed). Confirm that all
> > machines are living in
> > > the same zone. Sync'ing to ntp is good too
> although an
> > hour outage
> > > should be fine. If you want to protect against
> ntp
> > drift due to
> > > outage, you can run a canonical ntp server inside
> the
> > cluster. Given
> > > the NN has to be available for the cluster to
> > function, that might be
> > > a good place to run one and just have the DN /
> TT
> > nodes sync to it.
> > >
> > > HTH.
> > >
> > > On Wed, Apr 21, 2010 at 6:46 PM, Stuart Smith
> <st...@yahoo.com>
> > wrote:
> > >> Hello,
> > >> I've noticed an odd situation:
> > >>
> > >> The timestamps in my hadoop namenode log
> (and
> > filesystem) appear to be an hour behind the actual
> time on
> > the system (as supplied by `date`).
> > >>
> > >> I checked that this wasn't user error by
> stopping
> > and starting hadoop, and checking the most recent
> messages
> > (as well as the last time the file was modified).
> > >>
> > >> For example, you can see the last modified
> time,
> > and the timestamp on the shutdown log message
> different
> > significantly:
> > >>
> > >> stu@ubuntu-namenode:~/hadoop/logs$ ls -l
> > hadoop-stu-namenode-ubuntu-namenode.log
> > >> -rw-r--r-- 1 stu stu 22148124 2010-04-21
> 15:33
> > hadoop-stu-namenode-ubuntu-namenode.log
> > >> stu@ubuntu-namenode:~/hadoop/logs$ tail -f
> > hadoop-stu-namenode-ubuntu-namenode.log
> > >> ....
> > >> 2010-04-21 14:33:19,032 INFO
> > org.apache.hadoop.hdfs.server.namenode.NameNode:
> > SHUTDOWN_MSG:
> > >>
> >
> /************************************************************
> > >> SHUTDOWN_MSG: Shutting down NameNode at
> > ubuntu-namenode/192.168.193.87
> > >>
> >
> ************************************************************/
> > >>
> > >> I also checked this while hadoop was running:
> the
> > messages are consistently an hour behind.
> > >>
> > >> More troubling, this appears affect the
> filesystem
> > timestamps as well.
> > >>
> > >> stu@ubuntu-namenode:~/hadoop/bin$ date
> > >> Wed Apr 21 15:53:34 PDT 2010
> > >> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop
> dfs
> > -touchz /test
> > >> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop
> dfs -ls
> > /
> > >> Found 2 items
> > >> drwxr-xr-x - stu supergroup
> 0
> > 2010-04-20 16:51 /home
> > >> -rw-r--r-- 3 stu supergroup
> 0
> > 2010-04-21 14:53 /test
> > >>
> > >>
> > >> Interestingly, the datanodes appear to be
> fine:
> > >>
> > >> stu@ubuntu-hadoop-2:~/hadoop/logs$ ls -l
> > hadoop-stu-datanode-ubuntu-hadoop-2.log
> > >> -rw-r--r-- 1 stu stu 4918505 2010-04-21
> 15:47
> > hadoop-stu-datanode-ubuntu-hadoop-2.log
> > >> stu@ubuntu-hadoop-2:~/hadoop/logs$ tail -n 1
> > hadoop-stu-datanode-ubuntu-hadoop-2.log
> > >> 2010-04-21 15:47:21,875 INFO
> org.mortbay.log:
> > jetty-6.1.14
> > >>
> > >> Is there something wrong here? Am I just
> doing
> > something crazy/dumb?
> > >>
> > >> Note that I discovered this after getting
> some
> > rather odd behavior from hbase - hbase appears to work
> fine,
> > except it's continually adding the regionservers onto
> the
> > list so, in my itty-bitty cluster of about 4 machines
> + 1
> > namenode, the master reports back ~ 1000s of
> regionservers
> > and growing.. There are indications timing issues
> involved
> > in that as well, but I figure I should get hdfs
> working
> > first :)
> > >>
> > >> Note that I do have NTP running to keep all
> these
> > boxes in sync, but the NTP server will go down for an
> hour
> > or so intermittently (due to some network issues that
> don't
> > involve the hadoop cluster). All the system times on
> the
> > machines appear to be (at least) within a few seconds
> of
> > each other.
> > >>
> > >> I'm running hadoop 0.20.2
> > >>
> > >> Any thoughts? Any debugging guidance? I'm
> pretty
> > stumped.
> > >>
> > >> Take care,
> > >> -stu
> > >>
> > >>
> > >>
> > >>
> > >
> > >
> > >
> > > --
> > > Eric Sammer
> > > phone: +1-917-287-2675
> > > twitter: esammer
> > > data: www.cloudera.com
> > >
> >
> >
> >
> > --
> > Eric Sammer
> > phone: +1-917-287-2675
> > twitter: esammer
> > data: www.cloudera.com
> >
>
>
>
>
Re: hadoop log timestamps & file timestamps not same as system time
Posted by Stuart Smith <st...@yahoo.com>.
Hello Eric,
There's definitely an issue with timezones here (yes, deprecated, but to the point):
import java.util.Date;
import java.io.*;
class testDateTime
{
public static void main( String[] argv )
{
Date d = new Date();
System.out.println( "date: " + d.toString() );
}
}
says:
stu@ubuntu-namenode:~/testtime$ java testDateTime
date: Thu Apr 22 11:37:32 PST 2010
stu@ubuntu-namenode:~/testtime$ date
Thu Apr 22 12:37:34 PDT 2010
stu@ubuntu-namenode:~/testtime$ cat /etc/timezone
America/Los_Angeles
but then says:
stu@ubuntu-hadoop-1:~/testtime$ java testDateTime
date: Thu Apr 22 12:38:11 PDT 2010
stu@ubuntu-hadoop-1:~/testtime$ date
Thu Apr 22 12:38:12 PDT 2010
stu@ubuntu-hadoop-1:~/testtime$ cat /etc/timezone
America/Los_Angeles
Still digging into what's messing up java (or what java is messing up - every other program seems to be getting it right).
I've seen a couple posts around about localtime needing to be a symbolic link for java, etc, but they're all outdated, and not, apparently for ubuntu.
I've diff'd the localtime files from both machines, and they're the same, so something really odd is going on here.
But at least you got me heading in the right direction :)
Hopefully my next post will be the one with the answer..
Take care,
-stu
--- On Thu, 4/22/10, Eric Sammer <es...@cloudera.com> wrote:
> From: Eric Sammer <es...@cloudera.com>
> Subject: Re: hadoop log timestamps & file timestamps not same as system time
> To: hdfs-user@hadoop.apache.org, stu24mail@yahoo.com
> Date: Thursday, April 22, 2010, 2:00 AM
> Java *should* use the machine's
> configured TZ info (in whatever form
> that manifests as on the platform in question). For Linux,
> it usually
> means /etc/localtime and / or possibly the environment in
> which the
> jvm was executed. If I recall this may be set explicitly
> using some
> magic (i.e. undocumented) property one can pass to the jvm.
> As for the
> timestamps themselves, they're generated by log4j within
> the
> appropriate logging method (.info(), warn(), ...). The
> timezone
> selected is that of the host jvm within which the app is
> running.
>
> On Thu, Apr 22, 2010 at 1:39 AM, <st...@yahoo.com>
> wrote:
> > Cool thx!
> >
> > I already moved ntp to NN (had the same thought). All
> machines sync to the same apt-mirror, but I'll check the TZ
> files to make sure. Not much left to try...
> > I even formatted NN, and it didn't go away.
> >
> > Next would be to dig up hadoop source for timestamps,
> and run it in a harness, I guess. Could be java
> versioning/TZ issue, I suppose (Is java tzdata managed
> separately?)
> >
> > We'll see
> >
> > Best,
> > -stu
> > Sent from my Verizon Wireless BlackBerry
> >
> > -----Original Message-----
> > From: Eric Sammer <es...@cloudera.com>
> > Date: Thu, 22 Apr 2010 01:17:25
> > To: <hd...@hadoop.apache.org>
> > Subject: Re: hadoop log timestamps & file
> timestamps not same as system time
> >
> > My initial inclination is to check the timezone of the
> machines. An
> > hour difference smells like DST shift. Check that the
> OS are the same
> > version / patch level (as zoneinfo files may have
> changed based on
> > legislation recently passed). Confirm that all
> machines are living in
> > the same zone. Sync'ing to ntp is good too although an
> hour outage
> > should be fine. If you want to protect against ntp
> drift due to
> > outage, you can run a canonical ntp server inside the
> cluster. Given
> > the NN has to be available for the cluster to
> function, that might be
> > a good place to run one and just have the DN / TT
> nodes sync to it.
> >
> > HTH.
> >
> > On Wed, Apr 21, 2010 at 6:46 PM, Stuart Smith <st...@yahoo.com>
> wrote:
> >> Hello,
> >> I've noticed an odd situation:
> >>
> >> The timestamps in my hadoop namenode log (and
> filesystem) appear to be an hour behind the actual time on
> the system (as supplied by `date`).
> >>
> >> I checked that this wasn't user error by stopping
> and starting hadoop, and checking the most recent messages
> (as well as the last time the file was modified).
> >>
> >> For example, you can see the last modified time,
> and the timestamp on the shutdown log message different
> significantly:
> >>
> >> stu@ubuntu-namenode:~/hadoop/logs$ ls -l
> hadoop-stu-namenode-ubuntu-namenode.log
> >> -rw-r--r-- 1 stu stu 22148124 2010-04-21 15:33
> hadoop-stu-namenode-ubuntu-namenode.log
> >> stu@ubuntu-namenode:~/hadoop/logs$ tail -f
> hadoop-stu-namenode-ubuntu-namenode.log
> >> ....
> >> 2010-04-21 14:33:19,032 INFO
> org.apache.hadoop.hdfs.server.namenode.NameNode:
> SHUTDOWN_MSG:
> >>
> /************************************************************
> >> SHUTDOWN_MSG: Shutting down NameNode at
> ubuntu-namenode/192.168.193.87
> >>
> ************************************************************/
> >>
> >> I also checked this while hadoop was running: the
> messages are consistently an hour behind.
> >>
> >> More troubling, this appears affect the filesystem
> timestamps as well.
> >>
> >> stu@ubuntu-namenode:~/hadoop/bin$ date
> >> Wed Apr 21 15:53:34 PDT 2010
> >> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs
> -touchz /test
> >> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -ls
> /
> >> Found 2 items
> >> drwxr-xr-x - stu supergroup 0
> 2010-04-20 16:51 /home
> >> -rw-r--r-- 3 stu supergroup 0
> 2010-04-21 14:53 /test
> >>
> >>
> >> Interestingly, the datanodes appear to be fine:
> >>
> >> stu@ubuntu-hadoop-2:~/hadoop/logs$ ls -l
> hadoop-stu-datanode-ubuntu-hadoop-2.log
> >> -rw-r--r-- 1 stu stu 4918505 2010-04-21 15:47
> hadoop-stu-datanode-ubuntu-hadoop-2.log
> >> stu@ubuntu-hadoop-2:~/hadoop/logs$ tail -n 1
> hadoop-stu-datanode-ubuntu-hadoop-2.log
> >> 2010-04-21 15:47:21,875 INFO org.mortbay.log:
> jetty-6.1.14
> >>
> >> Is there something wrong here? Am I just doing
> something crazy/dumb?
> >>
> >> Note that I discovered this after getting some
> rather odd behavior from hbase - hbase appears to work fine,
> except it's continually adding the regionservers onto the
> list so, in my itty-bitty cluster of about 4 machines + 1
> namenode, the master reports back ~ 1000s of regionservers
> and growing.. There are indications timing issues involved
> in that as well, but I figure I should get hdfs working
> first :)
> >>
> >> Note that I do have NTP running to keep all these
> boxes in sync, but the NTP server will go down for an hour
> or so intermittently (due to some network issues that don't
> involve the hadoop cluster). All the system times on the
> machines appear to be (at least) within a few seconds of
> each other.
> >>
> >> I'm running hadoop 0.20.2
> >>
> >> Any thoughts? Any debugging guidance? I'm pretty
> stumped.
> >>
> >> Take care,
> >> -stu
> >>
> >>
> >>
> >>
> >
> >
> >
> > --
> > Eric Sammer
> > phone: +1-917-287-2675
> > twitter: esammer
> > data: www.cloudera.com
> >
>
>
>
> --
> Eric Sammer
> phone: +1-917-287-2675
> twitter: esammer
> data: www.cloudera.com
>
Re: hadoop log timestamps & file timestamps not same as system time
Posted by Eric Sammer <es...@cloudera.com>.
Java *should* use the machine's configured TZ info (in whatever form
that manifests as on the platform in question). For Linux, it usually
means /etc/localtime and / or possibly the environment in which the
jvm was executed. If I recall this may be set explicitly using some
magic (i.e. undocumented) property one can pass to the jvm. As for the
timestamps themselves, they're generated by log4j within the
appropriate logging method (.info(), warn(), ...). The timezone
selected is that of the host jvm within which the app is running.
On Thu, Apr 22, 2010 at 1:39 AM, <st...@yahoo.com> wrote:
> Cool thx!
>
> I already moved ntp to NN (had the same thought). All machines sync to the same apt-mirror, but I'll check the TZ files to make sure. Not much left to try...
> I even formatted NN, and it didn't go away.
>
> Next would be to dig up hadoop source for timestamps, and run it in a harness, I guess. Could be java versioning/TZ issue, I suppose (Is java tzdata managed separately?)
>
> We'll see
>
> Best,
> -stu
> Sent from my Verizon Wireless BlackBerry
>
> -----Original Message-----
> From: Eric Sammer <es...@cloudera.com>
> Date: Thu, 22 Apr 2010 01:17:25
> To: <hd...@hadoop.apache.org>
> Subject: Re: hadoop log timestamps & file timestamps not same as system time
>
> My initial inclination is to check the timezone of the machines. An
> hour difference smells like DST shift. Check that the OS are the same
> version / patch level (as zoneinfo files may have changed based on
> legislation recently passed). Confirm that all machines are living in
> the same zone. Sync'ing to ntp is good too although an hour outage
> should be fine. If you want to protect against ntp drift due to
> outage, you can run a canonical ntp server inside the cluster. Given
> the NN has to be available for the cluster to function, that might be
> a good place to run one and just have the DN / TT nodes sync to it.
>
> HTH.
>
> On Wed, Apr 21, 2010 at 6:46 PM, Stuart Smith <st...@yahoo.com> wrote:
>> Hello,
>> I've noticed an odd situation:
>>
>> The timestamps in my hadoop namenode log (and filesystem) appear to be an hour behind the actual time on the system (as supplied by `date`).
>>
>> I checked that this wasn't user error by stopping and starting hadoop, and checking the most recent messages (as well as the last time the file was modified).
>>
>> For example, you can see the last modified time, and the timestamp on the shutdown log message different significantly:
>>
>> stu@ubuntu-namenode:~/hadoop/logs$ ls -l hadoop-stu-namenode-ubuntu-namenode.log
>> -rw-r--r-- 1 stu stu 22148124 2010-04-21 15:33 hadoop-stu-namenode-ubuntu-namenode.log
>> stu@ubuntu-namenode:~/hadoop/logs$ tail -f hadoop-stu-namenode-ubuntu-namenode.log
>> ....
>> 2010-04-21 14:33:19,032 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: SHUTDOWN_MSG:
>> /************************************************************
>> SHUTDOWN_MSG: Shutting down NameNode at ubuntu-namenode/192.168.193.87
>> ************************************************************/
>>
>> I also checked this while hadoop was running: the messages are consistently an hour behind.
>>
>> More troubling, this appears affect the filesystem timestamps as well.
>>
>> stu@ubuntu-namenode:~/hadoop/bin$ date
>> Wed Apr 21 15:53:34 PDT 2010
>> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -touchz /test
>> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -ls /
>> Found 2 items
>> drwxr-xr-x - stu supergroup 0 2010-04-20 16:51 /home
>> -rw-r--r-- 3 stu supergroup 0 2010-04-21 14:53 /test
>>
>>
>> Interestingly, the datanodes appear to be fine:
>>
>> stu@ubuntu-hadoop-2:~/hadoop/logs$ ls -l hadoop-stu-datanode-ubuntu-hadoop-2.log
>> -rw-r--r-- 1 stu stu 4918505 2010-04-21 15:47 hadoop-stu-datanode-ubuntu-hadoop-2.log
>> stu@ubuntu-hadoop-2:~/hadoop/logs$ tail -n 1 hadoop-stu-datanode-ubuntu-hadoop-2.log
>> 2010-04-21 15:47:21,875 INFO org.mortbay.log: jetty-6.1.14
>>
>> Is there something wrong here? Am I just doing something crazy/dumb?
>>
>> Note that I discovered this after getting some rather odd behavior from hbase - hbase appears to work fine, except it's continually adding the regionservers onto the list so, in my itty-bitty cluster of about 4 machines + 1 namenode, the master reports back ~ 1000s of regionservers and growing.. There are indications timing issues involved in that as well, but I figure I should get hdfs working first :)
>>
>> Note that I do have NTP running to keep all these boxes in sync, but the NTP server will go down for an hour or so intermittently (due to some network issues that don't involve the hadoop cluster). All the system times on the machines appear to be (at least) within a few seconds of each other.
>>
>> I'm running hadoop 0.20.2
>>
>> Any thoughts? Any debugging guidance? I'm pretty stumped.
>>
>> Take care,
>> -stu
>>
>>
>>
>>
>
>
>
> --
> Eric Sammer
> phone: +1-917-287-2675
> twitter: esammer
> data: www.cloudera.com
>
--
Eric Sammer
phone: +1-917-287-2675
twitter: esammer
data: www.cloudera.com
Re: hadoop log timestamps & file timestamps not same as system time
Posted by st...@yahoo.com.
Cool thx!
I already moved ntp to NN (had the same thought). All machines sync to the same apt-mirror, but I'll check the TZ files to make sure. Not much left to try...
I even formatted NN, and it didn't go away.
Next would be to dig up hadoop source for timestamps, and run it in a harness, I guess. Could be java versioning/TZ issue, I suppose (Is java tzdata managed separately?)
We'll see
Best,
-stu
Sent from my Verizon Wireless BlackBerry
-----Original Message-----
From: Eric Sammer <es...@cloudera.com>
Date: Thu, 22 Apr 2010 01:17:25
To: <hd...@hadoop.apache.org>
Subject: Re: hadoop log timestamps & file timestamps not same as system time
My initial inclination is to check the timezone of the machines. An
hour difference smells like DST shift. Check that the OS are the same
version / patch level (as zoneinfo files may have changed based on
legislation recently passed). Confirm that all machines are living in
the same zone. Sync'ing to ntp is good too although an hour outage
should be fine. If you want to protect against ntp drift due to
outage, you can run a canonical ntp server inside the cluster. Given
the NN has to be available for the cluster to function, that might be
a good place to run one and just have the DN / TT nodes sync to it.
HTH.
On Wed, Apr 21, 2010 at 6:46 PM, Stuart Smith <st...@yahoo.com> wrote:
> Hello,
> I've noticed an odd situation:
>
> The timestamps in my hadoop namenode log (and filesystem) appear to be an hour behind the actual time on the system (as supplied by `date`).
>
> I checked that this wasn't user error by stopping and starting hadoop, and checking the most recent messages (as well as the last time the file was modified).
>
> For example, you can see the last modified time, and the timestamp on the shutdown log message different significantly:
>
> stu@ubuntu-namenode:~/hadoop/logs$ ls -l hadoop-stu-namenode-ubuntu-namenode.log
> -rw-r--r-- 1 stu stu 22148124 2010-04-21 15:33 hadoop-stu-namenode-ubuntu-namenode.log
> stu@ubuntu-namenode:~/hadoop/logs$ tail -f hadoop-stu-namenode-ubuntu-namenode.log
> ....
> 2010-04-21 14:33:19,032 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: SHUTDOWN_MSG:
> /************************************************************
> SHUTDOWN_MSG: Shutting down NameNode at ubuntu-namenode/192.168.193.87
> ************************************************************/
>
> I also checked this while hadoop was running: the messages are consistently an hour behind.
>
> More troubling, this appears affect the filesystem timestamps as well.
>
> stu@ubuntu-namenode:~/hadoop/bin$ date
> Wed Apr 21 15:53:34 PDT 2010
> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -touchz /test
> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -ls /
> Found 2 items
> drwxr-xr-x - stu supergroup 0 2010-04-20 16:51 /home
> -rw-r--r-- 3 stu supergroup 0 2010-04-21 14:53 /test
>
>
> Interestingly, the datanodes appear to be fine:
>
> stu@ubuntu-hadoop-2:~/hadoop/logs$ ls -l hadoop-stu-datanode-ubuntu-hadoop-2.log
> -rw-r--r-- 1 stu stu 4918505 2010-04-21 15:47 hadoop-stu-datanode-ubuntu-hadoop-2.log
> stu@ubuntu-hadoop-2:~/hadoop/logs$ tail -n 1 hadoop-stu-datanode-ubuntu-hadoop-2.log
> 2010-04-21 15:47:21,875 INFO org.mortbay.log: jetty-6.1.14
>
> Is there something wrong here? Am I just doing something crazy/dumb?
>
> Note that I discovered this after getting some rather odd behavior from hbase - hbase appears to work fine, except it's continually adding the regionservers onto the list so, in my itty-bitty cluster of about 4 machines + 1 namenode, the master reports back ~ 1000s of regionservers and growing.. There are indications timing issues involved in that as well, but I figure I should get hdfs working first :)
>
> Note that I do have NTP running to keep all these boxes in sync, but the NTP server will go down for an hour or so intermittently (due to some network issues that don't involve the hadoop cluster). All the system times on the machines appear to be (at least) within a few seconds of each other.
>
> I'm running hadoop 0.20.2
>
> Any thoughts? Any debugging guidance? I'm pretty stumped.
>
> Take care,
> -stu
>
>
>
>
--
Eric Sammer
phone: +1-917-287-2675
twitter: esammer
data: www.cloudera.com
Re: hadoop log timestamps & file timestamps not same as system time
Posted by Eric Sammer <es...@cloudera.com>.
My initial inclination is to check the timezone of the machines. An
hour difference smells like DST shift. Check that the OS are the same
version / patch level (as zoneinfo files may have changed based on
legislation recently passed). Confirm that all machines are living in
the same zone. Sync'ing to ntp is good too although an hour outage
should be fine. If you want to protect against ntp drift due to
outage, you can run a canonical ntp server inside the cluster. Given
the NN has to be available for the cluster to function, that might be
a good place to run one and just have the DN / TT nodes sync to it.
HTH.
On Wed, Apr 21, 2010 at 6:46 PM, Stuart Smith <st...@yahoo.com> wrote:
> Hello,
> I've noticed an odd situation:
>
> The timestamps in my hadoop namenode log (and filesystem) appear to be an hour behind the actual time on the system (as supplied by `date`).
>
> I checked that this wasn't user error by stopping and starting hadoop, and checking the most recent messages (as well as the last time the file was modified).
>
> For example, you can see the last modified time, and the timestamp on the shutdown log message different significantly:
>
> stu@ubuntu-namenode:~/hadoop/logs$ ls -l hadoop-stu-namenode-ubuntu-namenode.log
> -rw-r--r-- 1 stu stu 22148124 2010-04-21 15:33 hadoop-stu-namenode-ubuntu-namenode.log
> stu@ubuntu-namenode:~/hadoop/logs$ tail -f hadoop-stu-namenode-ubuntu-namenode.log
> ....
> 2010-04-21 14:33:19,032 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: SHUTDOWN_MSG:
> /************************************************************
> SHUTDOWN_MSG: Shutting down NameNode at ubuntu-namenode/192.168.193.87
> ************************************************************/
>
> I also checked this while hadoop was running: the messages are consistently an hour behind.
>
> More troubling, this appears affect the filesystem timestamps as well.
>
> stu@ubuntu-namenode:~/hadoop/bin$ date
> Wed Apr 21 15:53:34 PDT 2010
> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -touchz /test
> stu@ubuntu-namenode:~/hadoop/bin$ ./hadoop dfs -ls /
> Found 2 items
> drwxr-xr-x - stu supergroup 0 2010-04-20 16:51 /home
> -rw-r--r-- 3 stu supergroup 0 2010-04-21 14:53 /test
>
>
> Interestingly, the datanodes appear to be fine:
>
> stu@ubuntu-hadoop-2:~/hadoop/logs$ ls -l hadoop-stu-datanode-ubuntu-hadoop-2.log
> -rw-r--r-- 1 stu stu 4918505 2010-04-21 15:47 hadoop-stu-datanode-ubuntu-hadoop-2.log
> stu@ubuntu-hadoop-2:~/hadoop/logs$ tail -n 1 hadoop-stu-datanode-ubuntu-hadoop-2.log
> 2010-04-21 15:47:21,875 INFO org.mortbay.log: jetty-6.1.14
>
> Is there something wrong here? Am I just doing something crazy/dumb?
>
> Note that I discovered this after getting some rather odd behavior from hbase - hbase appears to work fine, except it's continually adding the regionservers onto the list so, in my itty-bitty cluster of about 4 machines + 1 namenode, the master reports back ~ 1000s of regionservers and growing.. There are indications timing issues involved in that as well, but I figure I should get hdfs working first :)
>
> Note that I do have NTP running to keep all these boxes in sync, but the NTP server will go down for an hour or so intermittently (due to some network issues that don't involve the hadoop cluster). All the system times on the machines appear to be (at least) within a few seconds of each other.
>
> I'm running hadoop 0.20.2
>
> Any thoughts? Any debugging guidance? I'm pretty stumped.
>
> Take care,
> -stu
>
>
>
>
--
Eric Sammer
phone: +1-917-287-2675
twitter: esammer
data: www.cloudera.com