try catch mechanisms and inlining

> Hello all, > > I wrote some basic debugging / profiling tools for xquery code, using > try{} catch *{} mechanisms. However, profiling tools are not reliable. > > The suspected reason is that inlining is not activated in try catch > expression. If confirmed, is it a desired behavior ? > > Here is the basic test : > > declare function local:test($i){fn:for-each(1 to $i, function($a){2*$a})}; > declare function local:fun-profile($fun,$args) > {try{local:call($fun,$args)} catch *{()}}; > declare function local:fun-profile2($fun,$args) {local:call($fun,$args)}; > > With default options (ie inlining activated) > > prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output > : 683.12 ms > prof:time(count(local:fun-profile(local:test#1, 10000000))) Output > : 2465.47 ms > > With inlining desactivated (ie INLINELIMIT=0) > prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output > : 2480.32 ms > >

On Sat, Jan 17, 2015 at 3:40 PM, jean-marc Mercier <jeanmarc.mercier at gmail.com> wrote: > Hello, > > To complete the previous threads : > 1) I forgot a definition : declare function local:call($fun,$args) > {$fun($args)}; > 2) The same behavior seems to occurs with the following code, not involving > try catch expression : > > declare function local:test($i){fn:for-each(1 to $i, function($a){2*$a})}; > declare variable $test := prof:time(local:test(10000000),false(),"2 :"); > prof:time(count(local:test(10000000)),false(),"1 :"),count($test) > > Output : > 2 :2508.42 ms > 1 :710.51 ms > > > > 2015-01-17 13:27 GMT+01:00 jean-marc Mercier <jeanmarc.mercier at gmail.com>: >> >> Hello all, >> >> I wrote some basic debugging / profiling tools for xquery code, using >> try{} catch *{} mechanisms. However, profiling tools are not reliable. >> >> The suspected reason is that inlining is not activated in try catch >> expression. If confirmed, is it a desired behavior ? >> >> Here is the basic test : >> >> declare function local:test($i){fn:for-each(1 to $i, function($a){2*$a})}; >> declare function local:fun-profile($fun,$args) >> {try{local:call($fun,$args)} catch *{()}}; >> declare function local:fun-profile2($fun,$args) {local:call($fun,$args)}; >> >> With default options (ie inlining activated) >> >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : >> 683.12 ms >> prof:time(count(local:fun-profile(local:test#1, 10000000))) Output : >> 2465.47 ms >> >> With inlining desactivated (ie INLINELIMIT=0) >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : >> 2480.32 ms >> >

> Hi Jean-Marc, > > This time, it was not that obvious to run your query (I stlil didn't > find local:call). But my guess is that the try/catch query is simply > slower, because catching errors simply takes time. I invite you to > look into the info view; it will show you what is inlined and what is > not. > > Best, > Christian > > > On Sat, Jan 17, 2015 at 3:40 PM, jean-marc Mercier > <jeanmarc.mercier at gmail.com> wrote: > > Hello, > > > > To complete the previous threads : > > 1) I forgot a definition : declare function local:call($fun,$args) > > {$fun($args)}; > > 2) The same behavior seems to occurs with the following code, not > involving > > try catch expression : > > > > declare function local:test($i){fn:for-each(1 to $i, > function($a){2*$a})}; > > declare variable $test := prof:time(local:test(10000000),false(),"2 :"); > > prof:time(count(local:test(10000000)),false(),"1 :"),count($test) > > > > Output : > > 2 :2508.42 ms > > 1 :710.51 ms > > > > > > > > 2015-01-17 13:27 GMT+01:00 jean-marc Mercier <jeanmarc.mercier at gmail.com > >: > >> > >> Hello all, > >> > >> I wrote some basic debugging / profiling tools for xquery code, using > >> try{} catch *{} mechanisms. However, profiling tools are not reliable. > >> > >> The suspected reason is that inlining is not activated in try catch > >> expression. If confirmed, is it a desired behavior ? > >> > >> Here is the basic test : > >> > >> declare function local:test($i){fn:for-each(1 to $i, > function($a){2*$a})}; > >> declare function local:fun-profile($fun,$args) > >> {try{local:call($fun,$args)} catch *{()}}; > >> declare function local:fun-profile2($fun,$args) > {local:call($fun,$args)}; > >> > >> With default options (ie inlining activated) > >> > >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : > >> 683.12 ms > >> prof:time(count(local:fun-profile(local:test#1, 10000000))) Output : > >> 2465.47 ms > >> > >> With inlining desactivated (ie INLINELIMIT=0) > >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : > >> 2480.32 ms > >> > > >

> Note that this analysis is quite difficult to > do because I can't use xquery info view for my "real" queries : the gui is > freezing. It appears that it is trying to dump an enormous map with which I > am working.

> > > declare function local:test($i){fn:for-each(1 to $i, function($a){2*$a})}; > declare function local:fun-profile($fun,$args) {try{$fun($args)} catch > *{()}}; > declare function local:fun-profile2($fun,$args) {$fun($args)}; > > prof:time(count(local:fun-profile(local:test#1, 10000000))) : 843.18 ms > (with BaseX gui) > > > 2015-01-17 17:00 GMT+01:00 Christian Grün <christian.gruen at gmail.com>: >> >> Hi Jean-Marc, >> >> This time, it was not that obvious to run your query (I stlil didn't >> find local:call). But my guess is that the try/catch query is simply >> slower, because catching errors simply takes time. I invite you to >> look into the info view; it will show you what is inlined and what is >> not. >> >> Best, >> Christian >> >> >> On Sat, Jan 17, 2015 at 3:40 PM, jean-marc Mercier >> <jeanmarc.mercier at gmail.com> wrote: >> > Hello, >> > >> > To complete the previous threads : >> > 1) I forgot a definition : declare function local:call($fun,$args) >> > {$fun($args)}; >> > 2) The same behavior seems to occurs with the following code, not >> > involving >> > try catch expression : >> > >> > declare function local:test($i){fn:for-each(1 to $i, >> > function($a){2*$a})}; >> > declare variable $test := prof:time(local:test(10000000),false(),"2 :"); >> > prof:time(count(local:test(10000000)),false(),"1 :"),count($test) >> > >> > Output : >> > 2 :2508.42 ms >> > 1 :710.51 ms >> > >> > >> > >> > 2015-01-17 13:27 GMT+01:00 jean-marc Mercier >> > <jeanmarc.mercier at gmail.com>: >> >> >> >> Hello all, >> >> >> >> I wrote some basic debugging / profiling tools for xquery code, using >> >> try{} catch *{} mechanisms. However, profiling tools are not reliable. >> >> >> >> The suspected reason is that inlining is not activated in try catch >> >> expression. If confirmed, is it a desired behavior ? >> >> >> >> Here is the basic test : >> >> >> >> declare function local:test($i){fn:for-each(1 to $i, >> >> function($a){2*$a})}; >> >> declare function local:fun-profile($fun,$args) >> >> {try{local:call($fun,$args)} catch *{()}}; >> >> declare function local:fun-profile2($fun,$args) >> >> {local:call($fun,$args)}; >> >> >> >> With default options (ie inlining activated) >> >> >> >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : >> >> 683.12 ms >> >> prof:time(count(local:fun-profile(local:test#1, 10000000))) Output : >> >> 2465.47 ms >> >> >> >> With inlining desactivated (ie INLINELIMIT=0) >> >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : >> >> 2480.32 ms >> >> >> > > >

> Hi Jean-Marc, > > > Note that this analysis is quite difficult to > > do because I can't use xquery info view for my "real" queries : the gui > is > > freezing. It appears that it is trying to dump an enormous map with > which I > > am working. > > You can also print the query info with the command-line flag -V. > > Hope this helps, > C. > > > > > > > > declare function local:test($i){fn:for-each(1 to $i, > function($a){2*$a})}; > > declare function local:fun-profile($fun,$args) {try{$fun($args)} catch > > *{()}}; > > declare function local:fun-profile2($fun,$args) {$fun($args)}; > > > > prof:time(count(local:fun-profile(local:test#1, 10000000))) : 843.18 ms > > (with BaseX gui) > > > > > > 2015-01-17 17:00 GMT+01:00 Christian Grün <christian.gruen at gmail.com>: > >> > >> Hi Jean-Marc, > >> > >> This time, it was not that obvious to run your query (I stlil didn't > >> find local:call). But my guess is that the try/catch query is simply > >> slower, because catching errors simply takes time. I invite you to > >> look into the info view; it will show you what is inlined and what is > >> not. > >> > >> Best, > >> Christian > >> > >> > >> On Sat, Jan 17, 2015 at 3:40 PM, jean-marc Mercier > >> <jeanmarc.mercier at gmail.com> wrote: > >> > Hello, > >> > > >> > To complete the previous threads : > >> > 1) I forgot a definition : declare function local:call($fun,$args) > >> > {$fun($args)}; > >> > 2) The same behavior seems to occurs with the following code, not > >> > involving > >> > try catch expression : > >> > > >> > declare function local:test($i){fn:for-each(1 to $i, > >> > function($a){2*$a})}; > >> > declare variable $test := prof:time(local:test(10000000),false(),"2 > :"); > >> > prof:time(count(local:test(10000000)),false(),"1 :"),count($test) > >> > > >> > Output : > >> > 2 :2508.42 ms > >> > 1 :710.51 ms > >> > > >> > > >> > > >> > 2015-01-17 13:27 GMT+01:00 jean-marc Mercier > >> > <jeanmarc.mercier at gmail.com>: > >> >> > >> >> Hello all, > >> >> > >> >> I wrote some basic debugging / profiling tools for xquery code, using > >> >> try{} catch *{} mechanisms. However, profiling tools are not > reliable. > >> >> > >> >> The suspected reason is that inlining is not activated in try catch > >> >> expression. If confirmed, is it a desired behavior ? > >> >> > >> >> Here is the basic test : > >> >> > >> >> declare function local:test($i){fn:for-each(1 to $i, > >> >> function($a){2*$a})}; > >> >> declare function local:fun-profile($fun,$args) > >> >> {try{local:call($fun,$args)} catch *{()}}; > >> >> declare function local:fun-profile2($fun,$args) > >> >> {local:call($fun,$args)}; > >> >> > >> >> With default options (ie inlining activated) > >> >> > >> >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : > >> >> 683.12 ms > >> >> prof:time(count(local:fun-profile(local:test#1, 10000000))) Output > : > >> >> 2465.47 ms > >> >> > >> >> With inlining desactivated (ie INLINELIMIT=0) > >> >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output : > >> >> 2480.32 ms > >> >> > >> > > > > > >

> In this case it would be useless : it appears that the optimized query > consists in dumping this big map (about 400 000 000 integers), consisting in > several Giga octets of data when serialized.

> > 2015-01-17 18:27 GMT+01:00 Christian Grün <christian.gruen at gmail.com>: >> >> Hi Jean-Marc, >> >> > Note that this analysis is quite difficult to >> > do because I can't use xquery info view for my "real" queries : the gui >> > is >> > freezing. It appears that it is trying to dump an enormous map with >> > which I >> > am working. >> >> You can also print the query info with the command-line flag -V. >> >> Hope this helps, >> C. >> >> >> > >> > >> > declare function local:test($i){fn:for-each(1 to $i, >> > function($a){2*$a})}; >> > declare function local:fun-profile($fun,$args) {try{$fun($args)} catch >> > *{()}}; >> > declare function local:fun-profile2($fun,$args) {$fun($args)}; >> > >> > prof:time(count(local:fun-profile(local:test#1, 10000000))) : 843.18 ms >> > (with BaseX gui) >> > >> > >> > 2015-01-17 17:00 GMT+01:00 Christian Grün <christian.gruen at gmail.com>: >> >> >> >> Hi Jean-Marc, >> >> >> >> This time, it was not that obvious to run your query (I stlil didn't >> >> find local:call). But my guess is that the try/catch query is simply >> >> slower, because catching errors simply takes time. I invite you to >> >> look into the info view; it will show you what is inlined and what is >> >> not. >> >> >> >> Best, >> >> Christian >> >> >> >> >> >> On Sat, Jan 17, 2015 at 3:40 PM, jean-marc Mercier >> >> <jeanmarc.mercier at gmail.com> wrote: >> >> > Hello, >> >> > >> >> > To complete the previous threads : >> >> > 1) I forgot a definition : declare function local:call($fun,$args) >> >> > {$fun($args)}; >> >> > 2) The same behavior seems to occurs with the following code, not >> >> > involving >> >> > try catch expression : >> >> > >> >> > declare function local:test($i){fn:for-each(1 to $i, >> >> > function($a){2*$a})}; >> >> > declare variable $test := prof:time(local:test(10000000),false(),"2 >> >> > :"); >> >> > prof:time(count(local:test(10000000)),false(),"1 :"),count($test) >> >> > >> >> > Output : >> >> > 2 :2508.42 ms >> >> > 1 :710.51 ms >> >> > >> >> > >> >> > >> >> > 2015-01-17 13:27 GMT+01:00 jean-marc Mercier >> >> > <jeanmarc.mercier at gmail.com>: >> >> >> >> >> >> Hello all, >> >> >> >> >> >> I wrote some basic debugging / profiling tools for xquery code, >> >> >> using >> >> >> try{} catch *{} mechanisms. However, profiling tools are not >> >> >> reliable. >> >> >> >> >> >> The suspected reason is that inlining is not activated in try catch >> >> >> expression. If confirmed, is it a desired behavior ? >> >> >> >> >> >> Here is the basic test : >> >> >> >> >> >> declare function local:test($i){fn:for-each(1 to $i, >> >> >> function($a){2*$a})}; >> >> >> declare function local:fun-profile($fun,$args) >> >> >> {try{local:call($fun,$args)} catch *{()}}; >> >> >> declare function local:fun-profile2($fun,$args) >> >> >> {local:call($fun,$args)}; >> >> >> >> >> >> With default options (ie inlining activated) >> >> >> >> >> >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output >> >> >> : >> >> >> 683.12 ms >> >> >> prof:time(count(local:fun-profile(local:test#1, 10000000))) Output >> >> >> : >> >> >> 2465.47 ms >> >> >> >> >> >> With inlining desactivated (ie INLINELIMIT=0) >> >> >> prof:time(count(local:fun-profile2(local:test#1, 10000000))) Output >> >> >> : >> >> >> 2480.32 ms >> >> >> >> >> > >> > >> > > >