[7.7] Glorp Store 10x slower publishing base

_______________________________________________
vwnc mailing list
[hidden email]
http://lists.cs.uiuc.edu/mailman/listinfo/vwnc

Thanks for pointing that out. It's odd that that happens, because that constant hasn't changed in a long time. I suspect that something in the database drivers or else in Glorp is causing it to use the large object buffer for things that it didn't used to. But I also don't know why we don't see this effect internally. Anyway, we'll need to look into it.

At 11:06 AM 2010-02-11, Steven Kelly wrote:

Content-class: urn:content-classes:message
Content-Type: multipart/alternative;
         boundary="----_=_NextPart_001_01CAAB34.34270EF5"

Publishing to Store has become an order of magnitude slower for me in 7.7 compared to earlier versions. Publishing the base differences (reconciled with 7.6) was taking several hours. The garbage collect cursor was showing all the time, but actual memory usage was staying constant (we set the growth upper bound to 64MB; I tried upping it to 128MB but that seemed just to slow things down further).
 
The garbage was being created in ODBCLargeObjectBuffer>>bindInputExternal, where it breaks the buffer of SQL arguments into chunks. In the line:
 
self at: 1 put: (valueStream nextAvailable:  (bufferSession getDataChunkSize min: cbValueMax)).
 
both “bufferSession getDataChunkSize” and cbValueMax were 1MB. Each time this line was sent the system thus allocated a new 1MB ByteArray in #nextAvailable. Since that won’t fit in Eden or LargeSpace (by default <300KB), it went straight to OldSpace, which quickly filled to the growth upper bound. When the next allocation failed it triggered a full compacting GC of all but PermSpace, which takes something of the order of a second. Saving the image with new startup sizes to make LargeSpace big enough would probably have helped, but the real problem was that the actual content of valueStream was almost always much less than the ByteArray allocated.
 
I thus made a quick hack of adding “min: bufferValue size”, i.e. no bigger than the total collection from which valueStream is being read. This seemed to solve the problem.
 
The only downside is that now I have my hacky fix published as part of the 7.7 base… Anyone have hints as to the Glorp Store invocation to make my 7.7 version of ODBCEXDI point to the 7.6 version of that method?!
 
Also, it’s odd that things slowed down now, if that method is unchanged; presumably something else changed elsewhere in the code, since our environment is unchanged from 7.6 (Win XP to SQLServer 2000 over a 100Mbps LAN).
 
Steve
_______________________________________________
vwnc mailing list
[hidden email]
http://lists.cs.uiuc.edu/mailman/listinfo/vwnc

_______________________________________________
vwnc mailing list
[hidden email]
http://lists.cs.uiuc.edu/mailman/listinfo/vwnc

_______________________________________________
vwnc mailing list
[hidden email]
http://lists.cs.uiuc.edu/mailman/listinfo/vwnc

Actually we use all of Oracle, Postgresql, and SQL Server internally. But we publish even the base incrementally, so it's possible some effect just wouldn't have gotten noticed. Thanks for the additional info, and we'll see what we can figure out.

At 09:58 AM 2010-02-12, Steven Kelly wrote:

One reason I get this and you don’t might be that we are on SQL Server and you are presumably on Oracle. Any other SQL Server users out there publish the base?
 
It’s possible that the delay would appear for us now in 7.6 too, i.e. that it’s something else in our environment that changed. It certainly wasn’t there when I published the base in May 2008. When publishing our own packages’ versions since then it’s quite possible we didn’t notice when the delay appeared, since the number of changes per publish is small. Since May 2008 I have over 200 Microsoft updates, including XP SP3, plus 35 updates on the server. I won’t try and guess if any of those could affect ODBC buffer behavior…
 
I just published a single package (RTP) from 7.6, and noticed the gc cursor flashing – but it only took a few seconds, not a few tens of seconds.
 
Here are the times it took to automatically publish the changed and already reconciled packages of each VW version, based on the timestamps of the first and last package published.
 
ver         publ.     mins      packages
7.4.1      July06    4:32        119
7.5          May08  3:51        211
7.6          May08  3:47        194
7.7          Feb10    119:41   227
 
Interestingly, the first 172 packages for 7.7 are bunched with from 6 to 116 packages on the same timestamp, then a big gap until the next timestamp. I interrupted the publish a few times with Process Monitor since it was so slow, but let it proceed within a minute or two. The last 55 packages for 7.7 were published after my fix, taking a few seconds each with no bunching of timestamps. The last 55 took 5:48 – so still several times slower than before. See the attached timestamp lists if you need more details.
 
Steve
 
From: Alan Knight [[hidden email]]
Sent: 11 February 2010 21:49
To: Steven Kelly; vwnc NC
Subject: Re: [vwnc] [7.7] Glorp Store 10x slower publishing base
 
Thanks for pointing that out. It's odd that that happens, because that constant hasn't changed in a long time. I suspect that something in the database drivers or else in Glorp is causing it to use the large object buffer for things that it didn't used to. But I also don't know why we don't see this effect internally. Anyway, we'll need to look into it.

At 11:06 AM 2010-02-11, Steven Kelly wrote:

Content-class: urn:content-classes:message
Content-Type: multipart/alternative;
         boundary="----_=_NextPart_001_01CAAB34.34270EF5"

Publishing to Store has become an order of magnitude slower for me in 7.7 compared to earlier versions. Publishing the base differences (reconciled with 7.6) was taking several hours. The garbage collect cursor was showing all the time, but actual memory usage was staying constant (we set the growth upper bound to 64MB; I tried upping it to 128MB but that seemed just to slow things down further).
 
The garbage was being created in ODBCLargeObjectBuffer>>bindInputExternal, where it breaks the buffer of SQL arguments into chunks. In the line:
 
self at: 1 put: (valueStream nextAvailable:  (bufferSession getDataChunkSize min: cbValueMax)).
 
both “bufferSession getDataChunkSize” and cbValueMax were 1MB. Each time this line was sent the system thus allocated a new 1MB ByteArray in #nextAvailable. Since that won’t fit in Eden or LargeSpace (by default <300KB), it went straight to OldSpace, which quickly filled to the growth upper bound. When the next allocation failed it triggered a full compacting GC of all but PermSpace, which takes something of the order of a second. Saving the image with new startup sizes to make LargeSpace big enough would probably have helped, but the real problem was that the actual content of valueStream was almost always much less than the ByteArray allocated.
 
I thus made a quick hack of adding “min: bufferValue size”, i.e. no bigger than the total collection from which valueStream is being read. This seemed to solve the problem.
 
The only downside is that now I have my hacky fix published as part of the 7.7 base… Anyone have hints as to the Glorp Store invocation to make my 7.7 version of ODBCEXDI point to the 7.6 version of that method?!
 
Also, it’s odd that things slowed down now, if that method is unchanged; presumably something else changed elsewhere in the code, since our environment is unchanged from 7.6 (Win XP to SQLServer 2000 over a 100Mbps LAN).
 
Steve
_______________________________________________
vwnc mailing list
[hidden email]
http://lists.cs.uiuc.edu/mailman/listinfo/vwnc
 
--
Alan Knight [|], Engineering Manager, Cincom Smalltalk
[hidden email]
[hidden email]
http://www.cincom.com/smalltalk

_______________________________________________
vwnc mailing list
[hidden email]
http://lists.cs.uiuc.edu/mailman/listinfo/vwnc

_______________________________________________
vwnc mailing list
[hidden email]
http://lists.cs.uiuc.edu/mailman/listinfo/vwnc