From: Luigi Tommaseo <luigi@(email surpressed)>
Subject: timestamp on logs
   Date: Fri, 20 Jan 2006 11:34:45 -0500

Hi all,

any help would be appreciated.

Luigi Tommaseo
Digital Systems Manager
Senate Visual Effects
Twickenham Film Studios
St.Margarets
Twickenham
Middlesex
TW1 2AW

Tel: (Tel# suppressed)
luigi@(email surpressed)
www.senatevfx.com

Luigi Tommaseo wrote:

is there any way we can have time stamp on the logs? what we would like to do here is to create a network and server performance log and correlate it to the logs of the render boxes to see if the problems we are having in the conversion to mentalray are indeed related to network performance or something else.

Hi Luigi,

	Which logs, the frame logs, or the cpu accounting logs?

	There are several time stamps in the frame logs:

                o The file's date stamp on the log itself
                o The file's 'Started:' date stamp from the log, ie:

                     % grep Started: /path/to/log/0001
                     --   Started: Thu Jan 05 14:46:14 2006

	In the cpu accounting logs (rush/var/cpu.acct), there's date stamps
	on all the entries in time(2) format.

	You should be able to come up with a simple script to dive into
	all the cpu.acct logs, sort the entries by date, and then easily
	be able to cross reference the frames that rendered vs. the errors
	in your server performance log.

	I'd go for the cpu.acct logs on the remotes; those are easy to
	collect and sort, and has all the job title/owner/frame#/exit code
	info in them.

	You might also cross reference errors with your system logs on
	each render machine, ie. /var/log/messages (LINUX),
	/var/log/system.log (OSX), or the windows event manager logs.

--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Cel: (Tel# suppressed)
Fax: (Tel# suppressed)

thanks

Luigi Tommaseo
Digital Systems Manager
Senate Visual Effects
Twickenham Film Studios
St.Margarets
Twickenham
Middlesex
TW1 2AW

Tel: (Tel# suppressed)
luigi@(email surpressed)
www.senatevfx.com

On 20 Jan 2006, at 19:32, Greg Ercolano wrote:

[posted to rush.general]

Luigi Tommaseo wrote:

is there any way we can have time stamp on the logs? what we would like to do here is to create a network and server performance log and correlate it to the logs of the render boxes to see if the problems we are having in the conversion to mentalray are indeed related to network performance or something else.

Hi Luigi,

	Which logs, the frame logs, or the cpu accounting logs?

	There are several time stamps in the frame logs:

                o The file's date stamp on the log itself
                o The file's 'Started:' date stamp from the log, ie:

                     % grep Started: /path/to/log/0001
                     --   Started: Thu Jan 05 14:46:14 2006

	In the cpu accounting logs (rush/var/cpu.acct), there's date stamps
	on all the entries in time(2) format.

	You should be able to come up with a simple script to dive into
	all the cpu.acct logs, sort the entries by date, and then easily
	be able to cross reference the frames that rendered vs. the errors
	in your server performance log.

	I'd go for the cpu.acct logs on the remotes; those are easy to
	collect and sort, and has all the job title/owner/frame#/exit code
	info in them.

	You might also cross reference errors with your system logs on
	each render machine, ie. /var/log/messages (LINUX),
	/var/log/system.log (OSX), or the windows event manager logs.

--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Cel: (Tel# suppressed)
Fax: (Tel# suppressed)

Hi Luigi.

Out of interest are you seeing these memory exceptions on Linux render
nodes? I am more used to seeing that kind of thing with windows.

How about passing the log file through a script that adds date to the start
of each line. Some clever awk'ing and tee'ing could do I should think. 

 

|-----Original Message-----
|From: Luigi Tommaseo [mailto:luigi@tommaseo.me.uk] 
|Sent: Monday, 23 January 2006 9:26 PM
|To: void@(email surpressed)
|Subject: Re: timestamp on logs
|
|[posted to rush.general]
|
|well what we would like to have is the frame log with a time 
|stamp for each line to compare the time our renders throw 
|memory exceptions with the network spikes that we are seeing 
|to be able to see if there is a relation between the 2.
|at the moment it looks as if converting maya to mi throws 
|memory exception even though the ram is available. not sure 
|about what it is I would like to be able to rule out the 
|server performance.
|maybe some sort of logging of the server and the frame log 
|related to each other would help.
|
|thanks
|
|Luigi Tommaseo
|Digital Systems Manager
|Senate Visual Effects
|Twickenham Film Studios
|St.Margarets
|Twickenham
|Middlesex
|TW1 2AW
|
|Tel: (Tel# suppressed)
|luigi@(email surpressed)
|www.senatevfx.com
|
|On 20 Jan 2006, at 19:32, Greg Ercolano wrote:
|
|> [posted to rush.general]
|>
|> Luigi Tommaseo wrote:
|>> is there any way we can have time stamp on the logs? what we would 
|>> like to do here is to create a network and server 
|performance log and 
|>> correlate it to the logs of the render boxes to see if the problems 
|>> we are having in the conversion to mentalray are indeed related to 
|>> network  performance or something else.
|>
|> Hi Luigi,
|>
|> 	Which logs, the frame logs, or the cpu accounting logs?
|>
|> 	There are several time stamps in the frame logs:
|>
|>                 o The file's date stamp on the log itself
|>                 o The file's 'Started:' date stamp from the log, ie:
|>
|>                      % grep Started: /path/to/log/0001
|>                      --   Started: Thu Jan 05 14:46:14 2006
|>
|> 	In the cpu accounting logs (rush/var/cpu.acct), there's 
|date stamps
|> 	on all the entries in time(2) format.
|>
|> 	You should be able to come up with a simple script to dive into
|> 	all the cpu.acct logs, sort the entries by date, and then easily
|> 	be able to cross reference the frames that rendered vs. 
|the errors
|> 	in your server performance log.
|>
|> 	I'd go for the cpu.acct logs on the remotes; those are easy to
|> 	collect and sort, and has all the job 
|title/owner/frame#/exit code
|> 	info in them.
|>
|> 	You might also cross reference errors with your system logs on
|> 	each render machine, ie. /var/log/messages (LINUX),
|> 	/var/log/system.log (OSX), or the windows event manager logs.
|>
|> --
|> Greg Ercolano, erco@(email surpressed)
|> Rush Render Queue, http://seriss.com/rush/
|> Tel: xxx-xxx-xxxx
|> Cel: xxx-xxx-xxxx
|> Fax: xxx-xxx-xxx
|

Hi,

Luigi Tommaseo
Digital Systems Manager
Senate Visual Effects
Twickenham Film Studios
St.Margarets
Twickenham
Middlesex
TW1 2AW

Tel: (Tel# suppressed)
luigi@(email surpressed)
www.senatevfx.com

On 23 Jan 2006, at 22:43, Dylan Penhale wrote:

[posted to rush.general]

Hi Luigi.

Out of interest are you seeing these memory exceptions on Linux render
nodes? I am more used to seeing that kind of thing with windows.

How about passing the log file through a script that adds date to the start

of each line. Some clever awk'ing and tee'ing could do I should think.



|-----Original Message-----
|From: Luigi Tommaseo [mailto:luigi@tommaseo.me.uk]
|Sent: Monday, 23 January 2006 9:26 PM
|To: void@(email surpressed)
|Subject: Re: timestamp on logs
|
|[posted to rush.general]
|
|well what we would like to have is the frame log with a time
|stamp for each line to compare the time our renders throw
|memory exceptions with the network spikes that we are seeing
|to be able to see if there is a relation between the 2.
|at the moment it looks as if converting maya to mi throws
|memory exception even though the ram is available. not sure
|about what it is I would like to be able to rule out the
|server performance.
|maybe some sort of logging of the server and the frame log
|related to each other would help.
|
|thanks
|
|Luigi Tommaseo
|Digital Systems Manager
|Senate Visual Effects
|Twickenham Film Studios
|St.Margarets
|Twickenham
|Middlesex
|TW1 2AW
|
|Tel: (Tel# suppressed)
|luigi@(email surpressed)
|www.senatevfx.com
|
|On 20 Jan 2006, at 19:32, Greg Ercolano wrote:
|
|> [posted to rush.general]
|>
|> Luigi Tommaseo wrote:
|>> is there any way we can have time stamp on the logs? what we would
|>> like to do here is to create a network and server
|performance log and

|>> correlate it to the logs of the render boxes to see if the problems

|>> we are having in the conversion to mentalray are indeed related to
|>> network  performance or something else.
|>
|> Hi Luigi,
|>
|> 	Which logs, the frame logs, or the cpu accounting logs?
|>
|> 	There are several time stamps in the frame logs:
|>
|>                 o The file's date stamp on the log itself

|> o The file's 'Started:' date stamp from the log, ie:

|>
|>                      % grep Started: /path/to/log/0001
|>                      --   Started: Thu Jan 05 14:46:14 2006
|>
|> 	In the cpu accounting logs (rush/var/cpu.acct), there's
|date stamps
|> 	on all the entries in time(2) format.
|>
|> 	You should be able to come up with a simple script to dive into
|> 	all the cpu.acct logs, sort the entries by date, and then easily
|> 	be able to cross reference the frames that rendered vs.
|the errors
|> 	in your server performance log.
|>
|> 	I'd go for the cpu.acct logs on the remotes; those are easy to
|> 	collect and sort, and has all the job
|title/owner/frame#/exit code
|> 	info in them.
|>
|> 	You might also cross reference errors with your system logs on
|> 	each render machine, ie. /var/log/messages (LINUX),
|> 	/var/log/system.log (OSX), or the windows event manager logs.
|>
|> --
|> Greg Ercolano, erco@(email surpressed)
|> Rush Render Queue, http://seriss.com/rush/
|> Tel: xxx-xxx-xxxx
|> Cel: xxx-xxx-xxxx
|> Fax: xxx-xxx-xxx
|

Luigi Tommaseo wrote:

Hi,

it was at the end a misconfiguration for the swap file in fstab, the boxes were running with no swap partition whatsoever.

	D'oh!

	Well then, I guess forget all the perl stuff I just sent ;)

--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Cel: (Tel# suppressed)
Fax: (Tel# suppressed)

thanks

Luigi Tommaseo
Digital Systems Manager
Senate Visual Effects
Twickenham Film Studios
St.Margarets
Twickenham
Middlesex
TW1 2AW

Tel: (Tel# suppressed)
luigi@(email surpressed)
www.senatevfx.com

On 24 Jan 2006, at 10:33, Greg Ercolano wrote:

[posted to rush.general]

Luigi Tommaseo wrote:

Hi,

it was at the end a misconfiguration for the swap file in fstab, the boxes were running with no swap partition whatsoever.

	D'oh!

	Well then, I guess forget all the perl stuff I just sent ;)

--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Cel: (Tel# suppressed)
Fax: (Tel# suppressed)

Ouch!

 

|-----Original Message-----
|From: Luigi Tommaseo [mailto:luigi@tommaseo.me.uk] 
|Sent: Tuesday, 24 January 2006 9:31 PM
|To: void@(email surpressed)
|Subject: Re: timestamp on logs
|
|[posted to rush.general]
|
|Hi,
|it was at the end a misconfiguration for the swap file in 
|fstab, the boxes were running with no swap partition whatsoever.
|
|Luigi Tommaseo
|Digital Systems Manager
|Senate Visual Effects
|Twickenham Film Studios
|St.Margarets
|Twickenham
|Middlesex
|TW1 2AW
|
|Tel: (Tel# suppressed)
|luigi@(email surpressed)
|www.senatevfx.com
|
|On 23 Jan 2006, at 22:43, Dylan Penhale wrote:
|
|> [posted to rush.general]
|>
|> Hi Luigi.
|>
|> Out of interest are you seeing these memory exceptions on 
|Linux render 
|> nodes? I am more used to seeing that kind of thing with windows.
|>
|> How about passing the log file through a script that adds 
|date to the 
|> start of each line. Some clever awk'ing and tee'ing could do 
|I should 
|> think.
|>
|>
|>
|> |-----Original Message-----
|> |From: Luigi Tommaseo [mailto:luigi@tommaseo.me.uk]
|> |Sent: Monday, 23 January 2006 9:26 PM
|> |To: void@(email surpressed)
|> |Subject: Re: timestamp on logs
|> |
|> |[posted to rush.general]
|> |
|> |well what we would like to have is the frame log with a time stamp 
|> |for each line to compare the time our renders throw memory 
|exceptions 
|> |with the network spikes that we are seeing to be able to 
|see if there 
|> |is a relation between the 2.
|> |at the moment it looks as if converting maya to mi throws memory 
|> |exception even though the ram is available. not sure about 
|what it is 
|> |I would like to be able to rule out the server performance.
|> |maybe some sort of logging of the server and the frame log 
|related to 
|> |each other would help.
|> |
|> |thanks
|> |
|> |Luigi Tommaseo
|> |Digital Systems Manager
|> |Senate Visual Effects
|> |Twickenham Film Studios
|> |St.Margarets
|> |Twickenham
|> |Middlesex
|> |TW1 2AW
|> |
|> |Tel: 0208 607 8866
|> |luigi@(email surpressed)
|> |www.senatevfx.com
|> |
|> |On 20 Jan 2006, at 19:32, Greg Ercolano wrote:
|> |
|> |> [posted to rush.general]
|> |>
|> |> Luigi Tommaseo wrote:
|> |>> is there any way we can have time stamp on the logs? 
|what we would 
|> |>> like to do here is to create a network and server
|> |performance log and
|> |>> correlate it to the logs of the render boxes to see if the
|> problems
|> |>> we are having in the conversion to mentalray are indeed 
|related to 
|> |>> network  performance or something else.
|> |>
|> |> Hi Luigi,
|> |>
|> |> 	Which logs, the frame logs, or the cpu accounting logs?
|> |>
|> |> 	There are several time stamps in the frame logs:
|> |>
|> |>                 o The file's date stamp on the log itself
|> |>                 o The file's 'Started:' date stamp from the log,
|> ie:
|> |>
|> |>                      % grep Started: /path/to/log/0001
|> |>                      --   Started: Thu Jan 05 14:46:14 2006
|> |>
|> |> 	In the cpu accounting logs (rush/var/cpu.acct), there's
|> |date stamps
|> |> 	on all the entries in time(2) format.
|> |>
|> |> 	You should be able to come up with a simple script to dive into
|> |> 	all the cpu.acct logs, sort the entries by date, and then easily
|> |> 	be able to cross reference the frames that rendered vs.
|> |the errors
|> |> 	in your server performance log.
|> |>
|> |> 	I'd go for the cpu.acct logs on the remotes; those are easy to
|> |> 	collect and sort, and has all the job
|> |title/owner/frame#/exit code
|> |> 	info in them.
|> |>
|> |> 	You might also cross reference errors with your system logs on
|> |> 	each render machine, ie. /var/log/messages (LINUX),
|> |> 	/var/log/system.log (OSX), or the windows event manager logs.
|> |>
|> |> --
|> |> Greg Ercolano, erco@(email surpressed)
|> |> Rush Render Queue, http://seriss.com/rush/
|> |> Tel: xxx-xxx-xxxx
|> |> Cel: xxx-xxx-xxxx
|> |> Fax: xxx-xxx-xxx
|> |
|>
|

|well what we would like to have is the frame log with a time |stamp for each line to compare the time our renders throw |memory exceptions with the network spikes that we are seeing |to be able to see if there is a relation between the 2.

	You could add some code to the render scripts to append
	log start/end times to a file.

	Just define a function that does something like this:

require "ctime.pl";
sub LogTime($)
{
    my ($msg) = @_;
    open(FD, ">>/net/tmp/times.txt");
    my $s = sprintf("%8s %-16s %-16s %s %s %s", $msg, $ENV{RUSH_HOSTNAME}, $ENV{RUSH_JOBID}, $ENV{RUSH_PADFRAME}, time(), ctime(time()));
    syswrite(FD, $s, length($s));	# atomic write
    close(FD);
}

	..then just put these commands above and below the render command
	in the submit script to time stamp the renders:

LogTime("Start:");
#
# render commands here
#
LogTime("End:");

	You'll end up with a log for all renders on all machines
	that looks something like this:

         RenderHost       Jobid            Frm  time()     Date
         ----------       ---------        ---- ---------- ------------------------
  Start: feris            tahoe.244        0001 1138098098 Tue Jan 24  2:21:38 2006
    End: feris            tahoe.244        0001 1138098103 Tue Jan 24  2:21:43 2006
  Start: darwin           tahoe.244        0071 1138098103 Tue Jan 24  2:21:43 2006
    End: darwin           tahoe.244        0071 1138098108 Tue Jan 24  2:21:48 2006


    Then you can format the fields and data as you like.

    I'm thinking the syswrite() in the above will 'guarantee' the data
    stays synchronized (so you don't have lines of data intermingled)
    Under unix anyway, syswrite() is supposed to be atomic, even over NFS.

    Not sure about Windows.

|at the moment it looks as if converting maya to mi throws |memory exception even though the ram is available. not sure |about what it is I would like to be able to rule out the |server performance.

    Usually server performance just makes things slow,
    and would hopefully not throw exceptions.

|maybe some sort of logging of the server and the frame log |related to each other would help.

    Yes; if you write a separate script that writes the server's status
    into the above log, then you'd have the data all merged together already,
    establishing a pattern if their is one.


--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Cel: (Tel# suppressed)
Fax: (Tel# suppressed)