Re: DBD::Pg, DBD::Oracle and others are slow with threads due to DBIS

On 15/03/12 10:16, Martin J. Evans wrote:
> On 14/03/2012 10:20, Tim Bunce wrote:
>> On Wed, Mar 14, 2012 at 08:24:36AM +0100, H.Merijn Brand wrote:
>>> On Tue, 13 Mar 2012 21:44:06 +0000, Tim Bunce<[email protected]>
>>> wrote:
>>>
>>>> On Fri, Mar 02, 2012 at 03:11:17PM +0000, Tim Bunce wrote:
>>>>>> The second patch, which makes DBIS more efficient, is a lot more complex,
>>>>>> and more likely to break things (especially as it's changing a bunch of
>>>>>> macros that are directly #included by the DBD drivers. You may need to
>>>>>> bump API version numbers; I don't understand that bit.
>>>>> I'm concerned that changing the API, and thus forcing all compiled
>>>>> drivers to be recompiled at the same time the DBI is installed,
>>>>> isn't worth the gain. Especially as drivers shouldn't be using DBIS in
>>>>> any hot code anyway.
>>>> I finally got around to looking at DBD::Pg and was horrified to discover
>>>> the number of DBIS calls made by hot paths in the code. Most are hidden
>>>> behind various tracing macros. Even fetch calls 3 + 3 * num_of_fields!
>>> When hidden, it won't stand out to the maintainers.
>>>
>>> How do we/I see where it happens? Do you have a (short) guide to check
>>> if my/a DBD (CSV, Unify, File) uses those too?
>> The slowness of the DBIS macro is only relevant for compiled drivers.
>> The DBIS macro is used to get a pointer to the DBI's struct dbistate_st.
>> In non-threaded perls it's simply a static variable initialised once.
>> In threaded perls it's a macro that has to do more expensive work.
>>
>> For many years now all DBI handles have had their own pointer to
>> dbistate_st. Since almost all code in the driver has access to a handle
>> that's the best way to get the dbistate_st struct pointer.
>>
>> Essentially it means changing all instances of DBIS to DBIc_DBISTATE(imp_xxh)
>> (where imp_xxh can be any of the imp_dbh, imp_sth etc variables).
>>
>> Looking at DBIXS.h I see these other macros that use DBIS and thus
>> should be avoided in hot code:
>>
>> DBILOGFP => DBIc_LOGPIO(imp_xxh)
>> DBILOGMSG(...) => DBIc_DBISTATE(imp_xxh)->logmsg(...)
> DBD::ODBC had none of the above.
>> neatsvpv(...) => DBIc_DBISTATE(imp_xxh)->neatsvpv(...)
> DBD::ODBC had a number of these however, the suggested change does not work:
>
> original:
>
> if (DBIc_TRACE(imp_sth, DBD_TRACING, 0, 4)) {
> TRACE2(imp_sth, " ODBC_CLEAR_RESULTS '%s' => %s\n",
> key, neatsvpv(value,0));
> }
> new:
> if (DBIc_TRACE(imp_sth, DBD_TRACING, 0, 4)) {
> TRACE2(imp_sth, " ODBC_CLEAR_RESULTS '%s' => %s\n",
> key, (DBIc_DBISTATE(imp_sth)->neatsvpv(value,0)));
> }
>
> compiler error:
>
> dbdimp.c: In function 'odbc_clear_result_set':
> dbdimp.c:233: error: expected identifier before '(' token
> dbdimp.c: In function 'odbc_db_STORE_attrib':
> dbdimp.c:4672: warning: cast to pointer from integer of different size
> dbdimp.c:4677: warning: cast to pointer from integer of different size
> dmake: Error code 129, while making 'dbdimp.o'
>
> I've not really looked into it yet.
>
>> however, usually those are only called in tracing code so it may not be
>> worth the effort to change them.
> ok, but I'm happy to do it in my case.
>
> I've now changed DBD::ODBC to remove all unnecessary calls to D_imp_whatever.
>
>> The DBIh_COM(h) macro also uses DBIS but there's a chicken-and-egg
>> problem here since DBIh_COM is the underlying mechanism of the
>> D_imp_xxh(h) macros used to get the imp_xxh pointer. So it can't be
>> avoided. Yet more reason to apply Dave's changes.
>>
>> Tim.
>>
>> p.s. For the logic to control tracing I recommend the DBIc_TRACE macro
>> (or something driver-specific like it or built using it):
>> DBIc_TRACE(imp, flags, flag_level, fallback_level)
> I will change DBD::Oracle to use DBIc_TRACE at the weekend. I've started getting rid of DBIS from DBD::Oracle but as you said it is a bit of a PITA to do although not difficult.
>> That's true if flags match the handle trace flags& handle trace
>> level>= flag_level, OR if handle trace_level> fallback_level
>>
>> DBIc_TRACE(imp, 0, 0, 4) = if handle trace level>= 4
>> DBIc_TRACE(imp, DBDf_TRACE_FOO, 2, 4) = if tracing DBDf_TRACE_FOO& level>=2 OR level>=4
>> DBIc_TRACE(imp, DBDf_TRACE_FOO, 2, 0) = as above but never trace just due to level
>>
>> For example:
>>
>> if (DBIc_TRACE(imp_xxh, DBIf_TRACE_SQL|DBIf_TRACE_xxx, 3, 7)) {
>> PerlIO_printf(DBIc_LOGPIO(imp_sth), "\tThe %s wibbled the %s\n", ...);
>> }
> Martin

Argh, DBD::Oracle tracing is a mess wrt to this discussion:

ocitrace.h:

#define DBD_OCI_TRACEON	(DBIS->debug >= 6 || dbd_verbose>=6)
#define DBD_OCI_TRACEFP	(DBILOGFP)

#define OCIServerRelease_log_stat(sc,errhp,b,bl,ht,ver,stat)\
	stat =OCIServerRelease(sc,errhp,b,bl,ht,ver);\
	(DBD_OCI_TRACEON) \
			? PerlIO_printf(DBD_OCI_TRACEFP,\
				 "%sOCIServerRelease(%p)=%s\n",\
				 OciTp, sc,oci_status_name(stat)),stat \
	: stat

Every single OCI call uses DBD_OCI_TRACEON which in turn uses DBIS->debug and non have a imp_xxx handle so this is a very large change. Ensuring the code at each point an OCI call is made has an imp_xxh and getting the right one is going to be an awful job especially when a load of funcs in oci8.c don't even have a handle. I don't see an easy way to automate this change so I'm not sure I've got the stomach for this. If I do this will I really "see" some speed up as it is a lot of work.

Martin
-- 
Martin J. Evans
Easysoft Limited
http://www.easysoft.com