Re: [Modeling-users] ec.insert() timing

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

=2D----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On September 11, 2003 09:55 am, you wrote:
>     and report t_kvc, t_insert and t_save ?

ok, I did :=20

   pprint([t_kvc, t_insert, t_save])
           =20
and the result (with *NO* profiling going on) is (sorry for the
formating):

[[0.0012559890747070312,
  0.0015519857406616211,
  0.0014079809188842773,
  0.0012360811233520508,
  0.0012440681457519531,
  0.001253962516784668,
  0.0012469291687011719,
  0.001255035400390625,
  0.0012500286102294922,
  0.0014050006866455078,
  0.0016050338745117188,
  0.0012500286102294922,
  0.0012619495391845703,
  0.0012490749359130859,
  0.0015799999237060547,
  0.0012569427490234375,
  0.0012700557708740234,
  0.0012619495391845703,
  0.0012520551681518555,
  0.0014119148254394531,
  0.0012480020523071289,
  0.0012559890747070312,
  0.0014290809631347656,
  0.0012629032135009766,
  0.0012450218200683594,
  0.0012600421905517578,
  0.0012469291687011719,
  0.0012499094009399414,
  0.0012609958648681641,
  0.0012609958648681641,
  0.0012499094009399414,
  0.0014309883117675781,
  0.0012490749359130859,
  0.0012580156326293945,
  0.001256108283996582,
  0.0012530088424682617,
  0.0015770196914672852,
  0.0012530088424682617,
  0.0012511014938354492,
  0.0012699365615844727,
  0.0012640953063964844,
  0.0014120340347290039,
  0.0012450218200683594,
  0.0015490055084228516,
  0.0012459754943847656,
  0.0012530088424682617,
  0.00156402587890625,
  0.0014159679412841797,
  0.0012350082397460938,
  0.0012639760971069336,
  0.0012480020523071289,
  0.0015670061111450195,
  0.0012700557708740234,
  0.0012509822845458984,
  0.0012459754943847656,
  0.0014040470123291016,
  0.0012429952621459961,
  0.0012470483779907227,
  0.0012669563293457031,
  0.0012220144271850586,
  0.0014249086380004883,
  0.001273036003112793,
  0.00156402587890625,
  0.0012530088424682617,
  0.001259922981262207,
  0.0015740394592285156,
  0.0012480020523071289,
  0.0012640953063964844,
  0.0012450218200683594,
  0.0014100074768066406,
  0.0015610456466674805,
  0.0012609958648681641,
  0.0012549161911010742,
  0.0012720823287963867,
  0.0012459754943847656,
  0.0014209747314453125,
  0.0012519359588623047,
  0.0012470483779907227,
  0.0012470483779907227,
  0.0012509822845458984,
  0.0015619993209838867,
  0.0012420415878295898,
  0.0012559890747070312,
  0.0012569427490234375,
  0.0012480020523071289,
  0.001562952995300293,
  0.0015299320220947266,
  0.001256108283996582,
  0.0012440681457519531,
  0.0015490055084228516,
  0.0021089315414428711,
  0.0015860795974731445,
  0.0012379884719848633,
  0.0012689828872680664,
  0.0015679597854614258,
  0.0024440288543701172,
  0.001255035400390625,
  0.0012450218200683594,
  0.0014050006866455078,
  0.0015419721603393555],
 [1.9966299533843994,
  1.9969379901885986,
  1.9991899728775024,
  1.9998400211334229,
  1.9998140335083008,
  1.9989409446716309,
  1.5233700275421143,
  2.0757629871368408,
  2.0056970119476318,
  2.0016980171203613,
  2.0033340454101562,
  1.9996179342269897,
  1.9986929893493652,
  1.9990460872650146,
  1.9989680051803589,
  1.9983110427856445,
  2.0008178949356079,
  1.9969730377197266,
  1.9981610774993896,
  1.9982980489730835,
  1.9970279932022095,
  2.000012993812561,
  1.9982099533081055,
  1.9992450475692749,
  1.9985290765762329,
  2.0004779100418091,
  1.9987590312957764,
  2.0098719596862793,
  1.9988129138946533,
  1.9985009431838989,
  1.9981800317764282,
  1.9987269639968872,
  1.9986039400100708,
  1.9995909929275513,
  1.9970769882202148,
  1.9977390766143799,
  1.998181939125061,
  1.9989529848098755,
  1.9993369579315186,
  1.9985369443893433,
  1.9971719980239868,
  1.998412013053894,
  1.9972670078277588,
  2.0035970211029053,
  1.9960908889770508,
  1.9974290132522583,
  1.9964050054550171,
  1.9983960390090942,
  1.9978470802307129,
  1.9963589906692505,
  1.9999489784240723,
  2.030364990234375,
  1.99782395362854,
  2.0071769952774048,
  1.9968540668487549,
  2.0052520036697388,
  1.9974780082702637,
  2.0052690505981445,
  1.997094988822937,
  1.9970070123672485,
  1.9967869520187378,
  1.9971680641174316,
  1.9959059953689575,
  1.9986159801483154,
  2.0014950037002563,
  2.0054119825363159,
  2.0044909715652466,
  1.9959390163421631,
  1.99754798412323,
  2.0053850412368774,
  1.9957480430603027,
  1.9961370229721069,
  1.9969979524612427,
  1.9969429969787598,
  1.9963600635528564,
  1.9959028959274292,
  1.9961450099945068,
  1.9974430799484253,
  1.995980978012085,
  1.9960340261459351,
  1.995959997177124,
  2.0054160356521606,
  1.9965320825576782,
  1.9980199337005615,
  1.9968359470367432,
  1.9994961023330688,
  1.9959698915481567,
  1.9970650672912598,
  2.0057209730148315,
  2.0049780607223511,
  2.003493070602417,
  1.9966839551925659,
  2.0044209957122803,
  1.9966210126876831,
  1.9961740970611572,
  1.998405933380127,
  1.9961420297622681,
  2.0062381029129028,
  2.0116540193557739,
  2.0041409730911255],
 [0.039458036422729492,
  0.037539958953857422,
  0.036861062049865723,
  0.037307977676391602,
  0.037559032440185547,
  0.03775489330291748,
  0.047219991683959961,
  0.051325082778930664,
  0.036828041076660156,
  0.040776968002319336,
  0.037160038948059082,
  0.038051009178161621,
  0.037733078002929688,
  0.038002967834472656,
  0.03803706169128418,
  0.037999987602233887,
  0.047974109649658203,
  0.038440942764282227,
  0.039523005485534668,
  0.039058923721313477,
  0.036335945129394531,
  0.0384979248046875,
  0.037342071533203125,
  0.038197994232177734,
  0.044772028923034668,
  0.038097977638244629,
  0.037073969841003418,
  0.038112998008728027,
  0.038234949111938477,
  0.03847503662109375,
  0.038445949554443359,
  0.03744196891784668,
  0.037266016006469727,
  0.039924025535583496,
  0.038985013961791992,
  0.038390040397644043,
  0.037743091583251953,
  0.037485957145690918,
  0.038331985473632812,
  0.039402008056640625,
  0.03902900218963623,
  0.039088010787963867,
  0.042624950408935547,
  0.040650010108947754,
  0.039441943168640137,
  0.039898037910461426,
  0.038405895233154297,
  0.039148092269897461,
  0.040221929550170898,
  0.039301037788391113,
  0.04309391975402832,
  0.039062976837158203,
  0.03976595401763916,
  0.039913058280944824,
  0.061332941055297852,
  0.039245009422302246,
  0.041972041130065918,
  0.039283037185668945,
  0.03953397274017334,
  0.039782047271728516,
  0.039796948432922363,
  0.040288090705871582,
  0.039728999137878418,
  0.04366600513458252,
  0.040779948234558105,
  0.042225003242492676,
  0.040544033050537109,
  0.040629029273986816,
  0.039927005767822266,
  0.040782928466796875,
  0.040778994560241699,
  0.039677023887634277,
  0.039734005928039551,
  0.040410041809082031,
  0.040774941444396973,
  0.040843963623046875,
  0.03924095630645752,
  0.040840983390808105,
  0.040881037712097168,
  0.040665984153747559,
  0.041599035263061523,
  0.040225028991699219,
  0.039021968841552734,
  0.039937973022460938,
  0.047130942344665527,
  0.040129899978637695,
  0.040014982223510742,
  0.041290044784545898,
  0.041398048400878906,
  0.042516946792602539,
  0.039626955986022949,
  0.042227029800415039,
  0.040439963340759277,
  0.04065096378326416,
  0.044528961181640625,
  0.040642976760864258,
  0.040132045745849609,
  0.075582981109619141,
  0.042561054229736328,
  0.05450904369354248]]

> > Without profiling, CPU usage stays under 20%, thats why I think about
> > a lock synchronization problem.  I can't recall when this started
> > because I usually insert an item at a time but I'm pretty sure that it
> > have not alway been like this.  I'll try to downgrade my Modeling
> > version and to load an old model with less entities.

Exact same timing with 0.9-pre-10

> As I said, I do not understand. insertObject() does not lock anything
> on its own except the NotificationCenter (addObserver() is called in
> recordObject() called by insertObjectWithGlobalID() called by
> insertObject()), but I can't see any reason why it would hang there.
>
> I'm not surprised that it takes such a long time *when profiling*, but
> having about the same time when *not* profiling is astonishing --never
> seen this before.

I have the .profile if you think you can get anything out of it but
the profiler only reoport CPU time, no wall clock time so this problem
is invisible to him...

=2D --=20
Yannick Gingras
Byte Gardener, Savoir-faire Linux inc.
http://www.savoirfairelinux.com/

=2D----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.2 (GNU/Linux)

iD8DBQE/YIUVrhy5Fqn/MRARAm/GAJ9w2tAV1EOPJ6E0RNvrGDycMzQ60gCggn78
TXtGAaPTZl+llMWy9XfHn7U=3D
=3Du1Qr
=2D----END PGP SIGNATURE-----