On Tue, 2008-11-04 at 12:21 -0500, Raymond Dans wrote: > In debugging XCF-2985(XECS-1854), I noticed that there was a really long > delay in the sipXsupervisor log between when the XML/RPC request was > received (from Config) and when it was actually printed out (up to 2 > minutes in some cases). This in turn caused sipXConfig to timeout > waiting for a response on the success or failure of the replication. > > Note: sipXsupervisor currently doesn't have a config parameter for > setting the debug level and it is > defaulted right now to DEBUG. This explains why the XML/RPC > request is being logged. > > Further investigation showed that the OsSysLog facility seemed to be the > one causing this enormous delay and of course blocking sipXsupervisor > for most of that time until it passes on the complete message to another > task for actual logging. > > The logging facility seems to have a couple of methods > (OsSysLog::escape, OsSysLog::myvsprintf) which are allocating/resizing > UtlString(s) a high number of times in a lot of cases. The constant > resizing of the UtlString(s) is what is causing the large delays. > > I'd like to propose modifying the identified methods (escape and > myvsprintf) to be a little smarter in how its allocating the > UtlString(s) to avoid the resizing as much as possible. This will not > only resolve the replication issue but will probably make the logging a > lot more efficient. > > OsSysLog::escape > > - accepts a UtlString as source and returns an escaped version of the > source in another UtlString. > > - I'd like to modify the result (return) string so that its > size/capacity is set to be at least the size of the source UltString. > This will drastically reduce the amount of resizing that needs to occur. > > > ------------------------------------------------------------------------ > ----------------------------- > -Question: Would it be best to actually set the initial capacity to the > size of the source + some additional buffering since the escaped version > will actually be a longer. If so, then how much extra buffering should > I put? > ------------------------------------------------------------------------ > ----------------------------- > > > OsSysLog::myvsprintf > > - A version of vsprintf that stores the result in a UtlString. > > - This method starts by allocating a UtlString of 900 bytes and tries to > copy the initial string into it (after parm substitution). If it fails > because the string is too small, it doubles the size and tries again. > This continues until its successful. > > - I'd like to modify the allocation of the UtlString to be at least the > "sizeof" of the format character string passed in if its greater than > 900 bytes. This will reduce the amount of resizing that needs to occur > for strings longer than 900 bytes.
It would certainly make sense to start with a size at least that of the format string, since the output is (almost) certain to be at least as big. And as you note below, probably add some padding, although for most messages 10 or 20 bytes would suffice. But I'm wondering why we're seeing this problem -- even in the bad case of starting with a 900-byte string and doubling it successively to get a 1.5 Mb string, that's only 11 doublings, which would take longer than we'd like, but doesn't account for expanding 3 seconds to 2 minutes. More curiously, the code at line 12576 should avoid doubling when it is run with Glibc 2.1 or later, because vsnprintf returns the size of the string it needs, so there should be just one reallocation, and the delay should not be noticable. Have you logged the actual pattern of buffer sizes in myvsprintf? Given what you've seen, I'm sure that there's a problem here, but the code just shouldn't be showing those symptoms. > ------------------------------------------------------------------------ > ---------------------------- > -Question: Would it be best to actually set the initial capacity to the > "sizeof" of the format character string + some additional buffering > since the resulting UtlString will probably be longer. If so, then how > much extra buffering should I put? > ------------------------------------------------------------------------ > ---------------------------- > > > I have made these changes and tested the replication that was failing > before. > > My system had 2100 users defined and the delay in processing (becausing > of the logging) was 2 minutes. With my changes in place, the entire > sipXsupervisor replication (from reading, logging, replicating and > returning the result) was about 2 to 3 seconds. The size of the XML/RPC > request was approximately 1.5 Mb. > > I then pumped up the number of users to 3200 and the processing was now > about 4 seconds. Certainly much better than before. > > > Raymond > _______________________________________________ > sipx-dev mailing list > [email protected] > List Archive: http://list.sipfoundry.org/archive/sipx-dev > Unsubscribe: http://list.sipfoundry.org/mailman/listinfo/sipx-dev _______________________________________________ sipx-dev mailing list [email protected] List Archive: http://list.sipfoundry.org/archive/sipx-dev Unsubscribe: http://list.sipfoundry.org/mailman/listinfo/sipx-dev
