POE, log4perl and sqlite
Good day. I'm using a bit modified Sungo's TCP server (Using SocketFactory and ReadWrite). I'm using a plain Log4perl, not POE::Log4perl. Yesterday I got a crash with sqlite database lock. So basically I have 2 questions: 1) Do POE's sessions run in parallel? (ok, this might be obvious, but I have to be sure :) This might explain the database lock, as parallel session could write at the same time. Oddly this crash happens rarely. 2) Does POE::Component::Log4perl cure this problem? If there is no cure, will there be a problem with file based logging? I can switch from SQL to grep based search. Thanks, Antti
Re: POE, log4perl and sqlite
On Mon, 15 Oct 2012 10:11:32 +0300 Antti Linno wrote: > 1) Do POE's sessions run in parallel? Not unless you are forking. > 2) Does POE::Component::Log4perl cure this problem? Unknown. We need to see some code. I could speculate on a number of things potentially causing this issue. Are you spinning up more than one process? Do you have any children processes that are running? Do you use any other mechanism to read from the sqlite file? What does your database code look like? Are you using alarm() (perl's alarm, not POE::Kernel's). Anyhow without any code it is difficult to debug. Please nopaste some code so we can help you. -- Nicholas Perez XMPP/Email: n...@nickandperla.net https://metacpan.org/author/NPEREZ http://github.com/nperez
Re: POE, log4perl and sqlite
On Mon, 15 Oct 2012, Antti Linno wrote: 1) Do POE's sessions run in parallel? (ok, this might be obvious, but I have to be sure :) This might explain the database lock, as parallel session could write at the same time. Oddly this crash happens rarely. Is using the database spawning multiple processes within POE? POE by itself is single-process-single-threaded, but some components spawn multiple processes, like this one: http://cpansearch.perl.org/src/XANTUS/POE-Component-EasyDBI-1.23/lib/POE/Component/EasyDBI/SubProcess.pm If you have multiple processes within POE, then I guess getting a SQLite locked situation is possible. 2) Does POE::Component::Log4perl cure this problem? This component is just a thin wrapper around Log4perl, and doesn't do much except provide an easy to use POE-like interface. If you're using a single-process-single-threaded POE application, Log4perl won't have issues with multiple writes to a file. If you have multiple processes, there's easy ways to avoid overlapping writes, as outlined in the Log4perl FAQ: http://search.cpan.org/dist/Log-Log4perl/lib/Log/Log4perl/FAQ.pm#How_can_I_synchronize_access_to_an_appender? -- -- Mike Mike Schilli p...@perlmeister.com If there is no cure, will there be a problem with file based logging? I can switch from SQL to grep based search. Thanks, Antti
Re: POE, log4perl and sqlite
First of all, I have to apologise. Still no pastebin. But a general tree would be something like that. Main POE module, imported submodule1, imported submodule2. All 3 modules open the same logger conf and use the same sqlite file to append the log. Theoretically the log file could be locked, if all 3 or even 2 modules try to write at the same time. What would be the nice and tidy thing to do? Initialize logger in main POE module and pass it to submodules? I'm amazed, that lockups happens once in a blue moon. Maybe load is still not that big, that events per second are low. Thank you for your time. On Wed, Oct 17, 2012 at 6:38 PM, wrote: > On Mon, 15 Oct 2012, Antti Linno wrote: > >> 1) Do POE's sessions run in parallel? (ok, this might be obvious, but >> I have to be sure :) This might explain the database lock, as parallel >> session could write at the same time. Oddly this crash >> happens rarely. > > > Is using the database spawning multiple processes within POE? POE by > itself is single-process-single-threaded, but some components spawn > multiple processes, like this one: > > > http://cpansearch.perl.org/src/XANTUS/POE-Component-EasyDBI-1.23/lib/POE/Component/EasyDBI/SubProcess.pm > > If you have multiple processes within POE, then I guess getting a SQLite > locked situation is possible. > > >> 2) Does POE::Component::Log4perl cure this problem? > > > This component is just a thin wrapper around Log4perl, and doesn't do > much except provide an easy to use POE-like interface. > > If you're using a single-process-single-threaded POE application, > Log4perl won't have issues with multiple writes to a file. If you have > multiple processes, there's easy ways to avoid overlapping writes, as > outlined in the Log4perl FAQ: > > > http://search.cpan.org/dist/Log-Log4perl/lib/Log/Log4perl/FAQ.pm#How_can_I_synchronize_access_to_an_appender? > > -- > -- Mike > > Mike Schilli > p...@perlmeister.com > > >> >> If there is no cure, will there be a problem with file based logging? >> I can switch from SQL to grep based search. >> >> Thanks, >> Antti >> >
Re: POE, log4perl and sqlite
On Oct 18, 2012, at 07:58, Antti Linno wrote: > First of all, I have to apologise. Still no pastebin. We have to apologize, too. You're asking questions about code we cannot see. This impairs our ability to provide satisfying answers. > But a general tree would be something like that. > > Main POE module, imported submodule1, imported submodule2. All 3 > modules open the same logger conf and use the same sqlite file to > append the log. Theoretically the log file could be locked, if all 3 > or even 2 modules try to write at the same time. No. As others have said, POE doesn't pre-empt. Under ordinary circumstances, we expect all three modules to call Log::Log4perl sequentially rather than concurrently. We don't expect Log::Log4perl suffer from lock contention. It's very likely that something extraordinary is happening as a result of code we cannot see. Others have already outlined the most likely reasons for the symptoms you described. I hope you understand that's the best we can do without your cooperation. > What would be the nice and tidy thing to do? Initialize logger in main > POE module and pass it to submodules? That's such a good question that Log::Log4perl already answers it: "Why Log::Log4perl->get_logger and not Log::Log4perl->new? We don't want to create a new object every time. Usually in OO-Programming, you create an object once and use the reference to it to call its methods. However, this requires that you pass around the object to all functions and the last thing we want is pollute each and every function/method we're using with a handle to the Logger: [example omitted] "Instead, if a function/method wants a reference to the logger, it just calls the Logger's static get_logger($category) method to obtain a reference to the one and only possible logger object of a certain category. That's called a singleton if you're a Gamma fan." That quote is from http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_via_a_configuration_file -- Rocco Caputo
Re: POE, log4perl and sqlite
Thank you for your kind interest. The pastebins: log4perl.conf http://pastebin.com/nY4twgjS main file http://pastebin.com/ruYsu2qt application logic http://pastebin.com/hMyyBJ0U database interaction http://pastebin.com/Cq7d4geK As you can see, all the perl files are logging, main and application import database functions. I have snipped the application and database somewhat, but you could see the main structure and how I am doing the logging. Greetings. On Thu, Oct 18, 2012 at 4:19 PM, Rocco Caputo wrote: > On Oct 18, 2012, at 07:58, Antti Linno wrote: > >> First of all, I have to apologise. Still no pastebin. > > We have to apologize, too. You're asking questions about code we cannot see. > This impairs our ability to provide satisfying answers. > >> But a general tree would be something like that. >> >> Main POE module, imported submodule1, imported submodule2. All 3 >> modules open the same logger conf and use the same sqlite file to >> append the log. Theoretically the log file could be locked, if all 3 >> or even 2 modules try to write at the same time. > > No. As others have said, POE doesn't pre-empt. Under ordinary > circumstances, we expect all three modules to call Log::Log4perl sequentially > rather than concurrently. We don't expect Log::Log4perl suffer from lock > contention. > > It's very likely that something extraordinary is happening as a result of > code we cannot see. Others have already outlined the most likely reasons for > the symptoms you described. I hope you understand that's the best we can do > without your cooperation. > >> What would be the nice and tidy thing to do? Initialize logger in main >> POE module and pass it to submodules? > > That's such a good question that Log::Log4perl already answers it: > > "Why Log::Log4perl->get_logger and not Log::Log4perl->new? We don't want to > create a new object every time. Usually in OO-Programming, you create an > object once and use the reference to it to call its methods. However, this > requires that you pass around the object to all functions and the last thing > we want is pollute each and every function/method we're using with a handle > to the Logger: > > [example omitted] > > "Instead, if a function/method wants a reference to the logger, it just calls > the Logger's static get_logger($category) method to obtain a reference to the > one and only possible logger object of a certain category. That's called a > singleton if you're a Gamma fan." > > That quote is from > http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_via_a_configuration_file > > -- > Rocco Caputo
Re: POE, log4perl and sqlite
Every module seems to be re-initializing your logger. I don't know if it's harmful in your situation, but it's not recommended. Wherever you call Log::Log4perl::init($log_conf) try Log::Log4perl->init_once($log_conf) instead. See: http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_once_and_only_once Offhand I don't see anything else that would lock your log database. Maybe another program is locking it in SELECT? If that's true, the queries are taking too long for the bot to wait. Maybe you could optimize the table indexes so the queries complete in time. -- Rocco Caputo On Oct 19, 2012, at 07:04, Antti Linno wrote: > Thank you for your kind interest. > > The pastebins: > > log4perl.conf http://pastebin.com/nY4twgjS > main file http://pastebin.com/ruYsu2qt > application logic http://pastebin.com/hMyyBJ0U > database interaction http://pastebin.com/Cq7d4geK > > As you can see, all the perl files are logging, main and application > import database functions. I have snipped the application and database > somewhat, but you could see the main structure and how I am doing the > logging. > > Greetings. > > On Thu, Oct 18, 2012 at 4:19 PM, Rocco Caputo wrote: >> On Oct 18, 2012, at 07:58, Antti Linno wrote: >> >>> First of all, I have to apologise. Still no pastebin. >> >> We have to apologize, too. You're asking questions about code we cannot >> see. This impairs our ability to provide satisfying answers. >> >>> But a general tree would be something like that. >>> >>> Main POE module, imported submodule1, imported submodule2. All 3 >>> modules open the same logger conf and use the same sqlite file to >>> append the log. Theoretically the log file could be locked, if all 3 >>> or even 2 modules try to write at the same time. >> >> No. As others have said, POE doesn't pre-empt. Under ordinary >> circumstances, we expect all three modules to call Log::Log4perl >> sequentially rather than concurrently. We don't expect Log::Log4perl suffer >> from lock contention. >> >> It's very likely that something extraordinary is happening as a result of >> code we cannot see. Others have already outlined the most likely reasons >> for the symptoms you described. I hope you understand that's the best we >> can do without your cooperation. >> >>> What would be the nice and tidy thing to do? Initialize logger in main >>> POE module and pass it to submodules? >> >> That's such a good question that Log::Log4perl already answers it: >> >> "Why Log::Log4perl->get_logger and not Log::Log4perl->new? We don't want to >> create a new object every time. Usually in OO-Programming, you create an >> object once and use the reference to it to call its methods. However, this >> requires that you pass around the object to all functions and the last thing >> we want is pollute each and every function/method we're using with a handle >> to the Logger: >> >> [example omitted] >> >> "Instead, if a function/method wants a reference to the logger, it just >> calls the Logger's static get_logger($category) method to obtain a reference >> to the one and only possible logger object of a certain category. That's >> called a singleton if you're a Gamma fan." >> >> That quote is from >> http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_via_a_configuration_file >> >> -- >> Rocco Caputo
Re: POE, log4perl and sqlite
Ok, thanks for suggestion. No select is taking place, unless I do it manually and via sqlite client. The crash occurred in the middle of the night, so my interference can be ruled out :D Maybe I should move to a file based logging as this seems more robust. Thank you all for your time. On Fri, Oct 19, 2012 at 3:46 PM, Rocco Caputo wrote: > Every module seems to be re-initializing your logger. I don't know if it's > harmful in your situation, but it's not recommended. Wherever you call > Log::Log4perl::init($log_conf) try Log::Log4perl->init_once($log_conf) > instead. See: > http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_once_and_only_once > > Offhand I don't see anything else that would lock your log database. Maybe > another program is locking it in SELECT? If that's true, the queries are > taking too long for the bot to wait. Maybe you could optimize the table > indexes so the queries complete in time. > > -- > Rocco Caputo > > On Oct 19, 2012, at 07:04, Antti Linno wrote: > >> Thank you for your kind interest. >> >> The pastebins: >> >> log4perl.conf http://pastebin.com/nY4twgjS >> main file http://pastebin.com/ruYsu2qt >> application logic http://pastebin.com/hMyyBJ0U >> database interaction http://pastebin.com/Cq7d4geK >> >> As you can see, all the perl files are logging, main and application >> import database functions. I have snipped the application and database >> somewhat, but you could see the main structure and how I am doing the >> logging. >> >> Greetings. >> >> On Thu, Oct 18, 2012 at 4:19 PM, Rocco Caputo wrote: >>> On Oct 18, 2012, at 07:58, Antti Linno wrote: >>> First of all, I have to apologise. Still no pastebin. >>> >>> We have to apologize, too. You're asking questions about code we cannot >>> see. This impairs our ability to provide satisfying answers. >>> But a general tree would be something like that. Main POE module, imported submodule1, imported submodule2. All 3 modules open the same logger conf and use the same sqlite file to append the log. Theoretically the log file could be locked, if all 3 or even 2 modules try to write at the same time. >>> >>> No. As others have said, POE doesn't pre-empt. Under ordinary >>> circumstances, we expect all three modules to call Log::Log4perl >>> sequentially rather than concurrently. We don't expect Log::Log4perl >>> suffer from lock contention. >>> >>> It's very likely that something extraordinary is happening as a result of >>> code we cannot see. Others have already outlined the most likely reasons >>> for the symptoms you described. I hope you understand that's the best we >>> can do without your cooperation. >>> What would be the nice and tidy thing to do? Initialize logger in main POE module and pass it to submodules? >>> >>> That's such a good question that Log::Log4perl already answers it: >>> >>> "Why Log::Log4perl->get_logger and not Log::Log4perl->new? We don't want to >>> create a new object every time. Usually in OO-Programming, you create an >>> object once and use the reference to it to call its methods. However, this >>> requires that you pass around the object to all functions and the last >>> thing we want is pollute each and every function/method we're using with a >>> handle to the Logger: >>> >>> [example omitted] >>> >>> "Instead, if a function/method wants a reference to the logger, it just >>> calls the Logger's static get_logger($category) method to obtain a >>> reference to the one and only possible logger object of a certain category. >>> That's called a singleton if you're a Gamma fan." >>> >>> That quote is from >>> http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_via_a_configuration_file >>> >>> -- >>> Rocco Caputo >
