# Problem - logging for mt programs

**URL:** <https://www.ruby-forum.com/t/problem-logging-for-mt-programs/68732>\
**Category:** Ruby\
**Created:** [September 15, 2006, 12:02am UTC](https://www.ruby-forum.com/t/problem-logging-for-mt-programs/68732 "2006-09-15T00:02:41Z")\
**Posts on this page:** 3\
**Page:** 1

<div class="post-metadata">

**Author:** ![unknown](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/u/4bbf92/32.png) [@unknown](https://www.ruby-forum.com/u/unknown)\
**Post date:** [September 15, 2006, 12:02am UTC](https://www.ruby-forum.com/t/problem-logging-for-mt-programs/68732/1 "2006-09-15T00:02:41Z")

</div>

anyone out there have good ways of dealing with multithreaded logging?  
my  
current approach uses a meta programming hack/mutex/etc so that, if the  
calling thread is the main one, a tid is not written, otherwise it is.  
thus,

I, [2006-09-14T15:41:58.394355 #14588] INFO – : aquired lock.

I, [2006-09-14T15:41:59.225737 #14588] INFO – : t[-609956564] command  
\<DDB\_GEN\_DIR=/dev/shm/fod/gen  
DDB\_OUT\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/out  
DDB\_LOG\_DIR=/dev/shm/fod/log DDB\_TMP\_DIR=/de v/shm/fod/tmp  
DDB\_EPH\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/eph.d  
DDB\_BVL\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/bvl.d DDB\_BVL\_EXE=false  
ddbasic -M nrt -n 2 -P ofdt -0.252525252525252 -P osdt  
-0.420875420875421 -S fod 2000.F12\_0010909\_DS.DAT  
2000.F12\_0011055\_DS.DAT\>

shows the first line being logged in the main thread, while the next  
line is  
logged by tid -609956564. this is ok. but, obviously, log lines become  
interleaved at a certian point leading to sections like

I, [2006-09-14T15:43:03.486280 #14588] INFO – : t[-610194194] command  
\<DDB\_GEN\_DIR=/dev/shm/foa/gen  
DDB\_OUT\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/foa/out  
DDB\_LOG\_DIR=/dev/shm/foa/log DDB\_TMP\_DIR=/dev/shm/foa/tmp  
DDB\_EPH\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/eph.d  
DDB\_BVL\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/bvl.d DDB\_BVL\_EXE=false  
ddbasic -M nrt -n 2 -P ofdt -0.252525252525252 -P osdt  
-0.420875420875421 -S foa 2000.F12\_0011232\_DS.DAT  
2000.F12\_0011414\_DS.DAT\>  
I, [2006-09-14T15:43:03.487003 #14588] INFO – : t[-610194894] tmp\_dir  
\</raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/tmp\>  
I, [2006-09-14T15:43:03.489989 #14588] INFO – : t[-610194894] command  
\<DDB\_GEN\_DIR=/dev/shm/fod/gen  
DDB\_OUT\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/out  
DDB\_LOG\_DIR=/dev/shm/fod/log DDB\_TMP\_DIR=/dev/shm/fod/tmp  
DDB\_EPH\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/eph.d  
DDB\_BVL\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/bvl.d DDB\_BVL\_EXE=false  
ddbasic -M nrt -n 2 -P ofdt -0.252525252525252 -P osdt  
-0.420875420875421 -S fod 2000.F12\_0011232\_DS.DAT  
2000.F12\_0011414\_DS.DAT\>  
I, [2006-09-14T15:44:18. 45782 #14588] INFO – : t[-610194894] status  
\<0\>  
I, [2006-09-14T15:44:18. 46468 #14588] INFO – : t[-610297924] command  
\<empty\_ols  
/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/out/F12200001010754.OIS\>  
I, [2006-09-14T15:44:18. 47187 #14588] INFO – : t[-610299344] command  
\<empty\_ols  
/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/out/F12200001010936.OIS\>  
I, [2006-09-14T15:44:18. 50663 #14588] INFO – : t[-610298484] command  
\<empty\_ols  
/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/out/F12200001011118.OIS\>  
I, [2006-09-14T15:44:18. 53356 #14588] INFO – : t[-610301254] command  
\<empty\_ols  
/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/out/F12200001011300.OIS\>  
I, [2006-09-14T15:44:25.361170 #14588] INFO – : t[-610194194] status  
\<0\>  
I, [2006-09-14T15:44:18. 50663 #14588] INFO – : t[-610297924] status  
\<0\>

here, we can certainly track the status of commands back the the  
line/thread  
that issued them, but it’s pretty painful to to by hand. of course, one  
could  
easily post-process in order to analyze…

so - has anyone else solved this problem neatly?

regards.

-a

---

<div class="post-metadata">

**Author:** ![unknown](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/u/4bbf92/32.png) [@unknown](https://www.ruby-forum.com/u/unknown)\
**Post date:** [September 16, 2006, 10:11pm UTC](https://www.ruby-forum.com/t/problem-logging-for-mt-programs/68732/2 "2006-09-16T22:11:00Z")

</div>

removed\_email\_address@domain.invalid wrote:

> anyone out there have good ways of dealing with multithreaded logging?

You mean other than assigning each thread a separate file?  
You probably have to either buffer messages more heavily, so they’re  
interleaved more coarsely, or if you want to write even more code, walk  
through the log file each time and insert the message in the appropriate  
place.

---

<div class="post-metadata">

**Author:** ![unknown](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/u/4bbf92/32.png) [@unknown](https://www.ruby-forum.com/u/unknown)\
**Post date:** [September 17, 2006, 3:41pm UTC](https://www.ruby-forum.com/t/problem-logging-for-mt-programs/68732/3 "2006-09-17T15:41:55Z")

</div>

removed\_email\_address@domain.invalid wrote:

> DDB\_OUT\_DIR=/raid/lv1/dmsp\_reprocessing/ddb/zwd.d/F12/fod/out  
> logged by tid -609956564. this is ok. but, obviously, log lines become  
> I, [2006-09-14T15:43:03.487003 #14588] INFO – : t[-610194894] tmp\_dir  
> I, [2006-09-14T15:44:18. 45782 #14588] INFO – : t[-610194894] status \<0\>  
> \<empty\_ols
> 
> so - has anyone else solved this problem neatly?  
> I handle this by having each thread _always_ drop its thread id into the  
> logs, whether it’s the main thread or not. However, I don’t do it as a  
> number - I write the entry at /usr/share/dict/words corresponding to the  
> thread id modulo the length of the file. That way, the threads are  
> identified by a memorable word rather than an unmemorable number, and  
> grep does the rest. It might not seem ground-breaking, but it makes the  
> whole thing much more friendly.

I’ve toyed in the past with assigning each thread a sequential ID, and  
altering the log output so that it’s actually a CSV file with the log  
output for each thread appearing in its own column, but that ended up  
being more trouble than it was worth at the time. I can dig the code up  
when I’m in the office tomorrow if you’re interested, but I’m sure  
you’re more than capable of replicating it without my help 🙂