Perfomance degradation in concat operations

[Ruslan Kvitunov]

Try out the two method implementation below. The time elapsed is
hardly dependent on use of
concatenation method

The classes are:
Class User.A Extends (%Persistent, %Populate)
{

Property SimpleProp
As %String;

Property Reference As User.B;

ClassMethod Concat(maxrows, method) As %String
{
set t0=$ZH
set rs=##class(%ResultSet).%New("User.A.Extent")
do rs.Execute()
set str=""
For i=1:1:maxrows {
quit:'rs.Next()
set obj=##class(User.A).%OpenId(rs.GetData(1))

if method=2 {
set var=obj.Reference.Name
set:method str=str_var
} else
{
set:method str=str_obj.Reference.Name
}
}
W !,"Method"_method_" time elapsed=",$ZH-t0,!
quit str
}

}

Class User.B Extends
(%Persistent, %Populate)
{

Property Name As %String;

}

Steps to reproduce the behaviour:
1)do ##class(User.B).Populate(1000000)
2)do ##class(User.A).Populate(1000000)
3)do ##class(User.A).Concat(50000,1) ;run method 1 on 50000 objects
Method1 time elapsed=64.947529
4)do ##class(User.A).Concat(50000,2) ;run method 2 on 50000 objects
Method2 time elapsed=4.131934

We get the huge difference
in time elapsed!! Method1 over 8 time slower than Method2!

The more rows we count the more
difference in time elapsed we get.

[Eric]

I reproduce the issue on 2009.1 (numbers are 50:2 instead of 64:4) on
a laptop. I strongly suggest to report this to ISC and post back the
WRC number here because this issue necessarily affects a lot of us.
Thanks for reporting this!

[Eric]

Comment from a colleague of mine:

"Very interesting, and strange. It only slows down as str grows
through each iteration. If str is reset to "" each time through the
loop, then the time is the same for both methods on my machine."

[htg]

not so impressive.

since time includes
- building the resultset
- opening object A
- swizzeling object B
- running a useless post-condtion
- WRITE to terminal on top
and a tiny little bit of atomic concatenation in between for naming
not to mention dependency on global buffers,
number of runs, .....

the measurement is interesting anyhow,
but the relation to concatenation is poor.
with same significance it could be
- 1 or 2 lines of code
- if or else branch

suggestion:
invest some time and visit the generated INT code behind

[Eric]

htg,

I agree the test could have been done differently but the issue was
first reproduced in identical context (as it should be) and the only
delta is the concat operation so the relation to concat is NOT poor.
It does show a reproducible issue with concat when the concat length
increases and when the concat involves an object property. We did
visit the INT code but if you had taken the trouble to test the issue
you would know nothing of interest can be seen there to explain the
issue. Although I did not post it, I also cleaned up the code and
tried a few other tests but without finding anything new; i.e. the
problem remains and cannot be explained (by me at least). It is not 2x
but 25x slower and this is a common operation so it is worth
investigating.

Do you have any constructive comment?

[htg]

On 5 Mai, 02:51, Eric <Eric.Ane...@gmail.com> wrote:
> Do you have any constructive comment?

simplified scenario still shows relation 3:1
so you are correct. there is a difference
Version 2009.1.FT3

USER>d ##class(C).M2(50000)
Method 2 time elapsed=2.309
Method 2 time elapsed=2.229
Method 2 time elapsed=2.271
USER>d ##class(C).M1(50000)
Method 1 time elapsed=7.58
Method 1 time elapsed=7.834
Method 1 time elapsed=7.509

Class User.C [ Abstract ]
{
ClassMethod M1(%maxrows) As %String {
set str="",t0=$ZH
for i=1:1:%maxrows {
set obj=##class(User.A).%OpenId(i)
set str=str_obj.Reference.Name
}
set t0=$Zh-t0
write !,"Method 1 time elapsed=",t0,!
}
ClassMethod M2(%maxrows) As %String {
set str="",t0=$ZH
for i=1:1:%maxrows {
set obj=##class(User.A).%OpenId(i)
set var=obj.Reference.Name
set str=str_var
}
set t0=$Zh-t0
write !,"Method 2 time elapsed=",t0,!
}
}

[Eric]

htg,

Just FYI, my own numbers were on FT2. Can't use FT3 yet.

[JoyPe...@gmail.com]

htg,

What hardware and OS are you testing on? I moved the object open
outside of the for loop for both tests to reduce the effect of
swizzling and unswizzling. I am now using the same object in every
concatenation operation. The numbers are much worse on a Macintosh:


Cache for UNIX (Apple Mac OS X for x86) 2008.2.1 (Build 902_0_7983U)
Mon Mar 30 2009 11:20:30 EDT

Method 1 time elapsed=96.45261
Method 1 time elapsed=96.134513
Method 1 time elapsed=97.038279

Method 2 time elapsed=.466633
Method 2 time elapsed=.488978
Method 2 time elapsed=.469039

Cache for UNIX (Apple Mac OS X for x86-64) 2009.1 (Build 401U) Sun Apr
12 2009 17:24:54 EDT

Method 1 time elapsed=53.520875
Method 1 time elapsed=53.614933
Method 1 time elapsed=54.044207

Method 2 time elapsed=.086315
Method 2 time elapsed=.084336
Method 2 time elapsed=.106758

We don't depend on the Macintosh for deployment, but I use it for a
development environment. My numbers are drastically different than
yours and I wonder if this might be attributed to either a difference
in hardware, or OS. I have noticed before that string intensive
routines are often much slower on a Macintosh server than with a
similar processor on Windows XP.

[htg]

that seems strongly dependend on HW/Memory speed
and dynamic / temporary memory allocation algorithms of OS/HW

> What hardware and OS are you testing on?

XEON based box offering 12 cores
32GB global buffers
RH EL5 over VMware
no visible concurrent activity
Cache for UNIX (Red Hat Enterprise Linux 5 for x86-64) 2009.1 (Build
401U)