Long load resulted in a hang


#1

I started my Big Load of 30+ years of climate data into SciDB last night. The files are broken up into months, so I have to juggle those 22 variables into a oneD array, insert them into the multidimensional array etc. I then do the same for each month’s data, and incrementally merge them with the master array.
I tried this scheme with tiny toy sets and it works (Thanks Alex for a previous posting…)

Now I am trying to go live with the real data, 388 months, 22 variables/attributes over dimensions height,Xdim,Ydim and open ended dimension: time (in months)

I get as far as about six months and then this error:

SystemException in file: src/smgr/io/Storage.cpp function: flush line: 1599 Error id: scidb::SCIDB_SE_STORAGE::SCIDB_LE_OPERATION_FAILED Error description: Storage error. Operation 'fsync' failed. Failed query id: 1102193404462

I tried to upload the attachment, but this site tells me “Tex extension is not allowed” I tried nothing, .txt, .log, none of these work.
So it is here (I removed everything before the query ID in question):

2012-10-09 21:49:14,442 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-09 21:49:14,442 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (127.0.0.1)
2012-10-09 21:49:14,442 [0x7fd3e5876700] [DEBUG]: Generated queryID: instanceID=0, time=1349833754, clock=1331942704, nextID=228, queryID=1102193404462
2012-10-09 21:49:14,442 [0x7fd3e5876700] [DEBUG]: Allocating query (1102193404462)
2012-10-09 21:49:14,442 [0x7fd3e5876700] [DEBUG]: Number of allocated queries = 1
2012-10-09 21:49:14,442 [0x7fd3e5876700] [DEBUG]: Initialized query (1102193404462)
2012-10-09 21:49:14,442 [0x7fd3e5876700] [DEBUG]: Parsing query(1102193404462): store(merge( temp, MerraMonthly ), MerraMonthly)
2012-10-09 21:49:14,447 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:197906,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,451 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-09 21:49:14,451 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:197906,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,452 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-09 21:49:14,452 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator merge: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:201007,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,454 [0x7fd3e5876700] [DEBUG]: Acquiring 2 array locks for query 1102193404462
2012-10-09 21:49:14,454 [0x7fd3e5876700] [DEBUG]: Acquiring lock: Lock: arrayName=MerraMonthly, arrayId=0, queryId=1102193404462, instanceId=0, instanceRole=COORD, lockMode=2, arrayVersion=0, arrayVersionId=0, timestamp=1288
2012-10-09 21:49:14,454 [0x7fd3e5876700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=MerraMonthly, arrayId=0, queryId=1102193404462, instanceId=0, instanceRole=COORD, lockMode=2, arrayVersion=0, arrayVersionId=0, timestamp=1288
2012-10-09 21:49:14,463 [0x7fd3e5876700] [DEBUG]: Acquiring lock: Lock: arrayName=temp, arrayId=0, queryId=1102193404462, instanceId=0, instanceRole=COORD, lockMode=1, arrayVersion=0, arrayVersionId=0, timestamp=1288
2012-10-09 21:49:14,463 [0x7fd3e5876700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=temp, arrayId=0, queryId=1102193404462, instanceId=0, instanceRole=COORD, lockMode=1, arrayVersion=0, arrayVersionId=0, timestamp=1288
2012-10-09 21:49:14,474 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:197906,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,478 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-09 21:49:14,478 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:197906,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,479 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-09 21:49:14,479 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator merge: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:201007,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,479 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:197906,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,480 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-09 21:49:14,480 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator merge: temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:201007,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
2012-10-09 21:49:14,480 [0x7fd3e5876700] [DEBUG]: Inferred schema for operator store: MerraMonthly<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
2012-10-09 21:49:14,480 [0x7fd3e5876700] [DEBUG]: The query is prepared
2012-10-09 21:49:14,480 [0x7fd3e5876700] [DEBUG]: The result preparation of query is sent to the client
2012-10-09 21:49:14,481 [0x7fd3ef66a700] [DEBUG]: Executing query(1102193404462): store(merge( temp, MerraMonthly ), MerraMonthly)
2012-10-09 21:49:14,481 [0x7fd3ef66a700] [DEBUG]: Creating Habilis optimizer instance
2012-10-09 21:49:14,486 [0x7fd3ef66a700] [DEBUG]: Query is optimized
2012-10-09 21:49:14,486 [0x7fd3ef66a700] [DEBUG]: The physical plan is detected as DML
2012-10-09 21:49:14,486 [0x7fd3ef66a700] [DEBUG]: 
[pPlan]:
>[pInstance] physicalStore agg 0 ddl 0 tile 0 children 1
  schema MerraMonthly<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
  props sgm 1 sgo 1
  distr roro
  bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 0.00386225 cells 25438500360 chunks 768 est_bytes 7.43751e+10
>>[pInstance] physicalMerge agg 0 ddl 0 tile 0 children 2
   schema temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:201007,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
   props sgm 1 sgo 1
   distr roro
   bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 0.00386225 cells 25438500360 chunks 768 est_bytes 7.43751e+10
>>>[pInstance] physicalScan agg 0 ddl 0 tile 1 children 0
    schema temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:197906,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
    props sgm 1 sgo 1
    distr roro
    bound start [197901, 0, 0, 0] end [197906, 41, 539, 360] density 1 cells 49124880 chunks 24 est_bytes 3.71875e+10
>>>[pInstance] physicalScan agg 0 ddl 0 tile 1 children 0
    schema MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
    props sgm 1 sgo 1
    distr roro
    bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 1 cells 25438500360 chunks 768 est_bytes 1.92569e+13

2012-10-09 21:49:14,486 [0x7fd3ef66a700] [DEBUG]: (Pre)Single executing queryID: 1102193404462
2012-10-09 21:49:14,521 [0x7fd3ef66a700] [DEBUG]: Create array MerraMonthly@9(955) in query 1102193404462
2012-10-09 21:49:14,530 [0x7fd3ef66a700] [DEBUG]: Query is serialized: [pPlan]:
>[pInstance] physicalStore agg 0 ddl 0 tile 0 children 1
  schema MerraMonthly@9<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
  props sgm 1 sgo 1
  distr roro
  bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 0.00386225 cells 25438500360 chunks 768 est_bytes 7.43751e+10
>>[pInstance] physicalMerge agg 0 ddl 0 tile 0 children 2
   schema temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:201007,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
   props sgm 1 sgo 1
   distr roro
   bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 0.00386225 cells 25438500360 chunks 768 est_bytes 7.43751e+10
>>>[pInstance] physicalScan agg 0 ddl 0 tile 1 children 0
    schema temp@1<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [daytemp=197701:197906,100,0,heighttemp=0:41,100,0,xdimtemp=0:539,100,0,ydimtemp=0:360,100,0]
    props sgm 1 sgo 1
    distr roro
    bound start [197901, 0, 0, 0] end [197906, 41, 539, 360] density 1 cells 49124880 chunks 24 est_bytes 3.71875e+10
>>>[pInstance] physicalScan agg 0 ddl 0 tile 1 children 0
    schema MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
    props sgm 1 sgo 1
    distr roro
    bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 1 cells 25438500360 chunks 768 est_bytes 1.92569e+13

2012-10-09 21:49:14,530 [0x7fd3ef66a700] [DEBUG]: Prepare physical plan was sent out
2012-10-09 21:49:14,530 [0x7fd3ef66a700] [DEBUG]: Waiting confirmation about preparing physical plan in queryID from 9 instances
2012-10-09 21:49:14,532 [0x7fd3e5775700] [DEBUG]: Notify on processing query 1102193404462 from instance 1
2012-10-09 21:49:14,532 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102193404462 from instance 2
2012-10-09 21:49:14,532 [0x7fd3e5674700] [DEBUG]: Notify on processing query 1102193404462 from instance 5
2012-10-09 21:49:14,532 [0x7fd3e5876700] [DEBUG]: Notify on processing query 1102193404462 from instance 4
2012-10-09 21:49:14,532 [0x7fd3e5674700] [DEBUG]: Notify on processing query 1102193404462 from instance 3
2012-10-09 21:49:14,532 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102193404462 from instance 6
2012-10-09 21:49:14,532 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102193404462 from instance 7
2012-10-09 21:49:14,532 [0x7fd3e5775700] [DEBUG]: Notify on processing query 1102193404462 from instance 9
2012-10-09 21:49:14,532 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102193404462 from instance 8
2012-10-09 21:49:14,532 [0x7fd3ef66a700] [DEBUG]: Execute physical plan was sent out
2012-10-09 21:49:14,532 [0x7fd3ef66a700] [INFO ]: Executing query(1102193404462): store(merge( temp, MerraMonthly ), MerraMonthly)
2012-10-09 21:49:14,534 [0x7fd3ef66a700] [DEBUG]: Request shared lock of array temp@1 for query 1102193404462
2012-10-09 21:49:14,534 [0x7fd3ef66a700] [DEBUG]: Granted shared lock of array temp@1 for query 1102193404462
2012-10-09 21:49:14,536 [0x7fd3ef66a700] [DEBUG]: Request shared lock of array MerraMonthly@8 for query 1102193404462
2012-10-09 21:49:14,536 [0x7fd3ef66a700] [DEBUG]: Granted shared lock of array MerraMonthly@8 for query 1102193404462
2012-10-09 21:49:14,536 [0x7fd3ef66a700] [DEBUG]: Request exclusive lock of array MerraMonthly for query 1102193404462
2012-10-09 21:49:14,536 [0x7fd3ef66a700] [DEBUG]: Granted exclusive lock of array MerraMonthly for query 1102193404462
2012-10-09 21:49:14,537 [0x7fd3ef66a700] [DEBUG]: Request shared lock of array MerraMonthly@9 for query 1102193404462
2012-10-09 21:49:14,538 [0x7fd3ef66a700] [DEBUG]: Granted shared lock of array MerraMonthly@9 for query 1102193404462
2012-10-09 21:57:35,118 [0x7fd3e5876700] [DEBUG]: Received query result from instance#8, queryID=1102193404462, arrayName=
2012-10-09 21:57:50,978 [0x7fd3e5674700] [DEBUG]: Received query result from instance#9, queryID=1102193404462, arrayName=
2012-10-09 21:58:57,257 [0x7fd3e5775700] [ERROR]: Error on processing query 1102193404462 on instance 1. Message: SystemException in file: src/smgr/io/Storage.cpp function: flush line: 1599
Error id: scidb::SCIDB_SE_STORAGE::SCIDB_LE_OPERATION_FAILED
Error description: Storage error. Operation 'fsync' failed.
Failed query id: 1102193404462
2012-10-09 21:59:00,769 [0x7fd3e496e700] [ERROR]: Job::execute: unhandled exception in job: SystemException in file: src/smgr/io/Storage.cpp function: flush line: 1599
Error id: scidb::SCIDB_SE_STORAGE::SCIDB_LE_OPERATION_FAILED
Error description: Storage error. Operation 'fsync' failed.
Failed query id: 1102193404462
2012-10-09 21:59:00,770 [0x7fd3ef66a700] [DEBUG]: Broadcast ABORT message to all instances for query 1102193404462
2012-10-09 21:59:00,771 [0x7fd3ef66a700] [DEBUG]: Query::done: queryID=1102193404462, _commitState=0, erorCode=33
2012-10-09 21:59:00,771 [0x7fd3ef66a700] [ERROR]: executeClientQuery failed to complete: SystemException in file: src/smgr/io/Storage.cpp function: flush line: 1599
Error id: scidb::SCIDB_SE_STORAGE::SCIDB_LE_OPERATION_FAILED
Error description: Storage error. Operation 'fsync' failed.
Failed query id: 1102193404462
2012-10-09 21:59:00,771 [0x7fd3ef66a700] [DEBUG]: Query (1102193404462) is being aborted
2012-10-09 21:59:00,771 [0x7fd3ef66a700] [ERROR]: Query (1102193404462) error handlers (1) are being executed
2012-10-09 21:59:00,771 [0x7fd3ef66a700] [DEBUG]: Update error handler is invoked for query (1102193404462)
2012-10-09 21:59:00,773 [0x7fd3ef66a700] [DEBUG]: UpdateErrorHandler::handleErrorOnCoordinator: the new version 9 of array MerraMonthly is being rolled back for query (1102193404462)
2012-10-09 21:59:00,803 [0x7fd3e5573700] [ERROR]: Error on processing query 1102193404462 on instance 2. Message: SystemException in file: src/query/Query.cpp function: handleAbort line: 527
Error id: scidb::SCIDB_SE_QPROC::SCIDB_LE_QUERY_CANCELLED
Error description: Query processor error. Query 1102193404462 was cancelled.
Failed query id: 1102193404462
2012-10-09 21:59:00,823 [0x7fd3e5876700] [DEBUG]: Query (1102193404462) is being aborted
2012-10-09 21:59:00,823 [0x7fd3e5876700] [DEBUG]: Deallocating query (1102193404462)
2012-10-09 21:59:00,988 [0x7fd3ef66a700] [DEBUG]: End of log at position 107224 rc=104
2012-10-09 21:59:00,988 [0x7fd3ef66a700] [DEBUG]: End of log at position 0 rc=0
2012-10-09 21:59:01,543 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-09 21:59:01,543 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (127.0.0.1)
2012-10-09 21:59:01,543 [0x7fd3e5674700] [DEBUG]: Generated queryID: instanceID=0, time=1349834341, clock=1911802704, nextID=229, queryID=1102773265050
2012-10-09 21:59:01,543 [0x7fd3e5674700] [DEBUG]: Allocating query (1102773265050)
2012-10-09 21:59:01,543 [0x7fd3e5674700] [DEBUG]: Number of allocated queries = 1
2012-10-09 21:59:01,543 [0x7fd3e5674700] [DEBUG]: Initialized query (1102773265050)
2012-10-09 21:59:01,543 [0x7fd3e5674700] [DEBUG]: Parsing query(1102773265050): remove(temp)
2012-10-09 21:59:01,589 [0x7fd3ef66a700] [DEBUG]: Releasing locks for query 1102193404462
2012-10-09 21:59:01,589 [0x7fd3ef66a700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1102193404462
2012-10-09 21:59:01,598 [0x7fd3ef66a700] [DEBUG]: Release lock of array MerraMonthly for query 1102193404462
2012-10-09 21:59:01,598 [0x7fd3ef66a700] [DEBUG]: Release lock of array MerraMonthly@8 for query 1102193404462
2012-10-09 21:59:01,598 [0x7fd3ef66a700] [DEBUG]: Release lock of array MerraMonthly@9 for query 1102193404462
2012-10-09 21:59:01,598 [0x7fd3ef66a700] [DEBUG]: Release lock of array temp@1 for query 1102193404462
2012-10-09 21:59:01,598 [0x7fd3ef66a700] [DEBUG]: Disconnected
2012-10-09 21:59:01,600 [0x7fd3e5674700] [DEBUG]: Acquiring 1 array locks for query 1102773265050
2012-10-09 21:59:01,600 [0x7fd3e5674700] [DEBUG]: Acquiring lock: Lock: arrayName=temp, arrayId=0, queryId=1102773265050, instanceId=0, instanceRole=COORD, lockMode=4, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-09 21:59:01,600 [0x7fd3e5674700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=temp, arrayId=0, queryId=1102773265050, instanceId=0, instanceRole=COORD, lockMode=4, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-09 21:59:01,609 [0x7fd3e5674700] [DEBUG]: Inferred schema for operator remove: temp<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
2012-10-09 21:59:01,609 [0x7fd3e5674700] [DEBUG]: The query is prepared
2012-10-09 21:59:01,609 [0x7fd3e5674700] [DEBUG]: The result preparation of query is sent to the client
2012-10-09 21:59:01,610 [0x7fd3e5775700] [DEBUG]: Executing query(1102773265050): remove(temp)
2012-10-09 21:59:01,610 [0x7fd3e5775700] [DEBUG]: Creating Habilis optimizer instance
2012-10-09 21:59:01,610 [0x7fd3e5775700] [DEBUG]: Query is optimized
2012-10-09 21:59:01,610 [0x7fd3e5775700] [DEBUG]: The physical plan is detected as DML
2012-10-09 21:59:01,610 [0x7fd3e5775700] [DEBUG]: 
[pPlan]:
>[pInstance] physicalRemove agg 0 ddl 0 tile 0 children 0
  schema temp<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
  props sgm 1 sgo 1
  distr roro
  bound start [197701, 0, 0, 0] end [4611686018427387903, 41, 539, 360] density 1 cells 4611686018427387903 chunks 4611686018427387903 est_bytes 4.19202e+21

2012-10-09 21:59:01,610 [0x7fd3e5775700] [DEBUG]: (Pre)Single executing queryID: 1102773265050
2012-10-09 21:59:01,611 [0x7fd3e5775700] [DEBUG]: Query is serialized: [pPlan]:
>[pInstance] physicalRemove agg 0 ddl 0 tile 0 children 0
  schema temp<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
  props sgm 1 sgo 1
  distr roro
  bound start [197701, 0, 0, 0] end [4611686018427387903, 41, 539, 360] density 1 cells 4611686018427387903 chunks 4611686018427387903 est_bytes 4.19202e+21

2012-10-09 21:59:01,611 [0x7fd3e5775700] [DEBUG]: Prepare physical plan was sent out
2012-10-09 21:59:01,611 [0x7fd3e5775700] [DEBUG]: Waiting confirmation about preparing physical plan in queryID from 9 instances
2012-10-09 21:59:01,612 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102773265050 from instance 3
2012-10-09 21:59:01,612 [0x7fd3e5876700] [DEBUG]: Notify on processing query 1102773265050 from instance 1
2012-10-09 21:59:01,612 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102773265050 from instance 2
2012-10-09 21:59:01,612 [0x7fd3e5674700] [DEBUG]: Notify on processing query 1102773265050 from instance 5
2012-10-09 21:59:01,612 [0x7fd3e5876700] [DEBUG]: Notify on processing query 1102773265050 from instance 7
2012-10-09 21:59:01,612 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102773265050 from instance 4
2012-10-09 21:59:01,612 [0x7fd3e5674700] [DEBUG]: Notify on processing query 1102773265050 from instance 8
2012-10-09 21:59:01,612 [0x7fd3e5876700] [DEBUG]: Notify on processing query 1102773265050 from instance 9
2012-10-09 21:59:01,612 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102773265050 from instance 6
2012-10-09 21:59:01,612 [0x7fd3e5775700] [DEBUG]: Execute physical plan was sent out
2012-10-09 21:59:01,612 [0x7fd3e5775700] [INFO ]: Executing query(1102773265050): remove(temp)
2012-10-09 21:59:01,612 [0x7fd3e5775700] [DEBUG]: Request exclusive lock of array temp for query 1102773265050
2012-10-09 21:59:01,612 [0x7fd3e5775700] [DEBUG]: Granted exclusive lock of array temp for query 1102773265050
2012-10-09 21:59:01,620 [0x7fd3e5674700] [DEBUG]: Received query result from instance#7, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,620 [0x7fd3e5674700] [DEBUG]: Received query result from instance#9, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,620 [0x7fd3e5876700] [DEBUG]: Received query result from instance#3, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,621 [0x7fd3e5573700] [DEBUG]: Received query result from instance#8, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,622 [0x7fd3e5775700] [DEBUG]: Query is executed locally
2012-10-09 21:59:01,628 [0x7fd3e5674700] [DEBUG]: Received query result from instance#1, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,652 [0x7fd3e5876700] [DEBUG]: Received query result from instance#2, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,706 [0x7fd3e5573700] [DEBUG]: Received query result from instance#5, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,724 [0x7fd3ef66a700] [DEBUG]: Received query result from instance#6, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,734 [0x7fd3e5674700] [DEBUG]: Received query result from instance#4, queryID=1102773265050, arrayName=
2012-10-09 21:59:01,734 [0x7fd3e5775700] [DEBUG]: The responses are received
2012-10-09 21:59:01,734 [0x7fd3e5775700] [DEBUG]: (Post)Single executing queryID: 1102773265050
2012-10-09 21:59:01,748 [0x7fd3e5775700] [DEBUG]: The result of query is returned
2012-10-09 21:59:01,748 [0x7fd3e5775700] [DEBUG]: The result of query is sent to the client
2012-10-09 21:59:01,748 [0x7fd3e5876700] [DEBUG]: Query (1102773265050) is committed
2012-10-09 21:59:01,748 [0x7fd3e5876700] [DEBUG]: Deallocating query (1102773265050)
2012-10-09 21:59:01,749 [0x7fd3e5876700] [DEBUG]: Releasing locks for query 1102773265050
2012-10-09 21:59:01,749 [0x7fd3e5876700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1102773265050
2012-10-09 21:59:01,756 [0x7fd3e5876700] [DEBUG]: Release lock of array temp for query 1102773265050
2012-10-09 21:59:01,758 [0x7fd3ef68a7c0] [DEBUG]: Disconnected
2012-10-09 21:59:01,772 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-09 21:59:01,772 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (127.0.0.1)
2012-10-09 21:59:01,772 [0x7fd3e5573700] [DEBUG]: Generated queryID: instanceID=0, time=1349834341, clock=1911842704, nextID=230, queryID=1102773305051
2012-10-09 21:59:01,772 [0x7fd3e5573700] [DEBUG]: Allocating query (1102773305051)
2012-10-09 21:59:01,772 [0x7fd3e5573700] [DEBUG]: Number of allocated queries = 1
2012-10-09 21:59:01,772 [0x7fd3e5573700] [DEBUG]: Initialized query (1102773305051)
2012-10-09 21:59:01,772 [0x7fd3e5573700] [DEBUG]: Parsing query(1102773305051): create array temp 
<
  H:float,
  T:float,
  U:float,
  V:float,
  QV:float,        
  O3:float,
  Cov_U_V:float,
  Cov_U_T:float,
  Cov_V_T:float,
  Cov_U_QV:float,
  Cov_V_QV:float,
  vsts:float,
  Var_H:float,
  Var_T:float,
  Var_U:float,
  Var_V:float,
  Var_QV:float,
  Var_O3:float
>
[
 day=197701:*,100,0,
 height=0:41,100,0,
 xdim=0:539,100,0,
 ydim=0:360,100,0]

2012-10-09 21:59:01,842 [0x7fd3e5573700] [DEBUG]: Acquiring 1 array locks for query 1102773305051
2012-10-09 21:59:01,842 [0x7fd3e5573700] [DEBUG]: Acquiring lock: Lock: arrayName=temp, arrayId=0, queryId=1102773305051, instanceId=0, instanceRole=COORD, lockMode=3, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-09 21:59:01,842 [0x7fd3e5573700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=temp, arrayId=0, queryId=1102773305051, instanceId=0, instanceRole=COORD, lockMode=3, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-09 21:59:01,865 [0x7fd3e5573700] [DEBUG]: Inferred schema for operator create_array: temp<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
2012-10-09 21:59:01,865 [0x7fd3e5573700] [DEBUG]: The query is prepared
2012-10-09 21:59:01,865 [0x7fd3e5573700] [DEBUG]: The result preparation of query is sent to the client
2012-10-09 21:59:01,866 [0x7fd3ef66a700] [DEBUG]: Executing query(1102773305051): create array temp 
<
  H:float,
  T:float,
  U:float,
  V:float,
  QV:float,        
  O3:float,
  Cov_U_V:float,
  Cov_U_T:float,
  Cov_V_T:float,
  Cov_U_QV:float,
  Cov_V_QV:float,
  vsts:float,
  Var_H:float,
  Var_T:float,
  Var_U:float,
  Var_V:float,
  Var_QV:float,
  Var_O3:float
>
[
 day=197701:*,100,0,
 height=0:41,100,0,
 xdim=0:539,100,0,
 ydim=0:360,100,0]

2012-10-09 21:59:01,866 [0x7fd3ef66a700] [DEBUG]: Creating Habilis optimizer instance
2012-10-09 21:59:01,866 [0x7fd3ef66a700] [DEBUG]: Query is optimized
2012-10-09 21:59:01,866 [0x7fd3ef66a700] [DEBUG]: The physical plan is detected as DDL
2012-10-09 21:59:01,866 [0x7fd3ef66a700] [DEBUG]: 
[pPlan]:
>[pInstance] impl_create_array agg 0 ddl 1 tile 0 children 0
  schema temp<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [day=197701:*,100,0,height=0:41,100,0,xdim=0:539,100,0,ydim=0:360,100,0]
  props sgm 1 sgo 1
  distr roro
  bound start [4611686018427387903, 4611686018427387903, 4611686018427387903, 4611686018427387903] end [-4611686018427387903, -4611686018427387903, -4611686018427387903, -4611686018427387903] density 1 cells 0 chunks 5772455505832953873 est_bytes 8.77413e+20

2012-10-09 21:59:01,866 [0x7fd3ef66a700] [DEBUG]: (Pre)Single executing queryID: 1102773305051
2012-10-09 21:59:01,866 [0x7fd3ef66a700] [INFO ]: Executing query(1102773305051): create array temp 
<
  H:float,
  T:float,
  U:float,
  V:float,
  QV:float,        
  O3:float,
  Cov_U_V:float,
  Cov_U_T:float,
  Cov_V_T:float,
  Cov_U_QV:float,
  Cov_V_QV:float,
  vsts:float,
  Var_H:float,
  Var_T:float,
  Var_U:float,
  Var_V:float,
  Var_QV:float,
  Var_O3:float
>
[
 day=197701:*,100,0,
 height=0:41,100,0,
 xdim=0:539,100,0,
 ydim=0:360,100,0]

2012-10-09 21:59:01,891 [0x7fd3ef66a700] [DEBUG]: Create array temp(956) in query 1102773305051
2012-10-09 21:59:01,891 [0x7fd3ef66a700] [DEBUG]: Query is executed locally
2012-10-09 21:59:01,891 [0x7fd3ef66a700] [DEBUG]: (Post)Single executing queryID: 1102773305051
2012-10-09 21:59:01,891 [0x7fd3ef66a700] [DEBUG]: The result of query is returned
2012-10-09 21:59:01,891 [0x7fd3ef66a700] [DEBUG]: The result of query is sent to the client
2012-10-09 21:59:01,892 [0x7fd3e5674700] [DEBUG]: Query (1102773305051) is committed
2012-10-09 21:59:01,892 [0x7fd3e5674700] [DEBUG]: Deallocating query (1102773305051)
2012-10-09 21:59:01,892 [0x7fd3e5674700] [DEBUG]: Releasing locks for query 1102773305051
2012-10-09 21:59:01,892 [0x7fd3e5674700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1102773305051
2012-10-09 21:59:01,901 [0x7fd3ef68a7c0] [DEBUG]: Disconnected
2012-10-09 21:59:01,914 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-09 21:59:01,914 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (127.0.0.1)
2012-10-09 21:59:01,914 [0x7fd3e5775700] [DEBUG]: Generated queryID: instanceID=0, time=1349834341, clock=1911912704, nextID=231, queryID=1102773375052
2012-10-09 21:59:01,914 [0x7fd3e5775700] [DEBUG]: Allocating query (1102773375052)
2012-10-09 21:59:01,914 [0x7fd3e5775700] [DEBUG]: Number of allocated queries = 1
2012-10-09 21:59:01,915 [0x7fd3e5775700] [DEBUG]: Initialized query (1102773375052)
2012-10-09 21:59:01,915 [0x7fd3e5775700] [DEBUG]: Parsing query(1102773375052): load(MerraRaw, '/tmp/load_pipe')
2012-10-09 21:59:01,919 [0x7fd3e5775700] [DEBUG]: Acquiring 1 array locks for query 1102773375052
2012-10-09 21:59:01,919 [0x7fd3e5775700] [DEBUG]: Acquiring lock: Lock: arrayName=MerraRaw, arrayId=0, queryId=1102773375052, instanceId=0, instanceRole=COORD, lockMode=2, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-09 21:59:01,919 [0x7fd3e5775700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=MerraRaw, arrayId=0, queryId=1102773375052, instanceId=0, instanceRole=COORD, lockMode=2, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-09 21:59:01,944 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator load: MerraRaw<day:int64,height:int64,xdim:int64,ydim:int64,H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [Line=0:*,1000000,0]
2012-10-09 21:59:01,945 [0x7fd3e5775700] [DEBUG]: The query is prepared
2012-10-09 21:59:01,945 [0x7fd3e5775700] [DEBUG]: The result preparation of query is sent to the client
2012-10-09 21:59:01,945 [0x7fd3e5876700] [DEBUG]: Executing query(1102773375052): load(MerraRaw, '/tmp/load_pipe')
2012-10-09 21:59:01,945 [0x7fd3e5876700] [DEBUG]: Creating Habilis optimizer instance
2012-10-09 21:59:01,945 [0x7fd3e5876700] [DEBUG]: Query is optimized
2012-10-09 21:59:01,945 [0x7fd3e5876700] [DEBUG]: The physical plan is detected as DML
2012-10-09 21:59:01,946 [0x7fd3e5876700] [DEBUG]: 
[pPlan]:
>[pInstance] impl_sg agg 0 ddl 0 tile 0 children 1
  schema MerraRaw<day:int64,height:int64,xdim:int64,ydim:int64,H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [Line=0:*,1000000,0]
  props sgm 0 sgo 0
  distr roro
  bound start [0] end [4611686018427387903] density 1 cells 4611686018427387903 chunks 4611686018427387903 est_bytes 2.6056e+21
>>[pInstance] impl_input agg 0 ddl 0 tile 0 children 0
   schema MerraRaw<day:int64,height:int64,xdim:int64,ydim:int64,H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [Line=0:*,1000000,0]
   props sgm 1 sgo 1
   distr loca instance 0
   bound start [0] end [4611686018427387903] density 1 cells 4611686018427387903 chunks 4611686018427387903 est_bytes 2.6056e+21

2012-10-09 21:59:01,946 [0x7fd3e5876700] [DEBUG]: (Pre)Single executing queryID: 1102773375052
2012-10-09 21:59:02,025 [0x7fd3e5876700] [DEBUG]: Create array MerraRaw@10(957) in query 1102773375052
2012-10-09 21:59:02,033 [0x7fd3e5876700] [DEBUG]: Query is serialized: [pPlan]:
>[pInstance] impl_sg agg 0 ddl 0 tile 0 children 1
  schema MerraRaw@10<day:int64,height:int64,xdim:int64,ydim:int64,H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [Line=0:*,1000000,0]
  props sgm 0 sgo 0
  distr roro
  bound start [0] end [4611686018427387903] density 1 cells 4611686018427387903 chunks 4611686018427387903 est_bytes 2.6056e+21
>>[pInstance] impl_input agg 0 ddl 0 tile 0 children 0
   schema MerraRaw<day:int64,height:int64,xdim:int64,ydim:int64,H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [Line=0:*,1000000,0]
   props sgm 1 sgo 1
   distr loca instance 0
   bound start [0] end [4611686018427387903] density 1 cells 4611686018427387903 chunks 4611686018427387903 est_bytes 2.6056e+21

2012-10-09 21:59:02,033 [0x7fd3e5876700] [DEBUG]: Prepare physical plan was sent out
2012-10-09 21:59:02,033 [0x7fd3e5876700] [DEBUG]: Waiting confirmation about preparing physical plan in queryID from 9 instances
2012-10-09 21:59:02,035 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102773375052 from instance 1
2012-10-09 21:59:02,035 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102773375052 from instance 2
2012-10-09 21:59:02,035 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102773375052 from instance 3
2012-10-09 21:59:02,035 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102773375052 from instance 5
2012-10-09 21:59:02,035 [0x7fd3e5775700] [DEBUG]: Notify on processing query 1102773375052 from instance 6
2012-10-09 21:59:02,035 [0x7fd3e5674700] [DEBUG]: Notify on processing query 1102773375052 from instance 7
2012-10-09 21:59:02,035 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102773375052 from instance 8
2012-10-09 21:59:02,035 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102773375052 from instance 9
2012-10-09 21:59:02,390 [0x7fd3ef68a7c0] [DEBUG]: Query 1102193404462 is not found
2012-10-09 21:59:02,401 [0x7fd3ef68a7c0] [ERROR]: Exception in message handler: messageType = 12
2012-10-09 21:59:02,403 [0x7fd3ef68a7c0] [ERROR]: Exception in message handler: source instance ID = instance 5
2012-10-09 21:59:02,403 [0x7fd3ef68a7c0] [ERROR]: Exception in message handler: SystemException in file: src/query/Query.cpp function: getQueryByID line: 767
Error id: scidb::SCIDB_SE_QPROC::SCIDB_LE_QUERY_NOT_FOUND
Error description: Query processor error. Query 1102193404462 not found.
Failed query id: 1102773375052
2012-10-09 21:59:03,314 [0x7fd3ef68a7c0] [DEBUG]: Disconnected
2012-10-09 21:59:03,906 [0x7fd3ef68a7c0] [DEBUG]: Disconnected
2012-10-09 21:59:04,152 [0x7fd3ef68a7c0] [DEBUG]: Disconnected
2012-10-09 21:59:05,471 [0x7fd3ef68a7c0] [DEBUG]: Disconnected
2012-10-09 21:59:07,854 [0x7fd3ef68a7c0] [ERROR]: Network error in handleSendMessage #104('Connection reset by peer'), instance 4 (10.0.0.4)
2012-10-09 21:59:07,855 [0x7fd3ef68a7c0] [DEBUG]: Recovering connection to instance 4
2012-10-09 21:59:07,855 [0x7fd3ef68a7c0] [ERROR]: Network error in handleSendMessage #104('Connection reset by peer'), instance 6 (10.0.0.6)
2012-10-09 21:59:07,855 [0x7fd3ef68a7c0] [DEBUG]: Recovering connection to instance 6
2012-10-09 21:59:07,894 [0x7fd3ef68a7c0] [DEBUG]: Connected to instance 4 (10.0.0.4), 10.0.0.4:1240
2012-10-09 21:59:07,894 [0x7fd3ef68a7c0] [DEBUG]: Connected to instance 6 (10.0.0.6), 10.0.0.6:1240
2012-10-09 21:59:12,752 [0x7fd3ef68a7c0] [ERROR]: Network error in handleSendMessage #32('Broken pipe'), instance 3 (10.0.0.3)
2012-10-09 21:59:12,752 [0x7fd3ef68a7c0] [DEBUG]: Recovering connection to instance 3
2012-10-09 21:59:12,752 [0x7fd3ef68a7c0] [ERROR]: Network error in handleSendMessage #32('Broken pipe'), instance 7 (10.0.0.7)
2012-10-09 21:59:12,752 [0x7fd3ef68a7c0] [DEBUG]: Recovering connection to instance 7
2012-10-09 21:59:12,782 [0x7fd3ef68a7c0] [DEBUG]: Connected to instance 3 (10.0.0.3), 10.0.0.3:1240
2012-10-09 21:59:12,782 [0x7fd3ef68a7c0] [DEBUG]: Connected to instance 7 (10.0.0.7), 10.0.0.7:1240
2012-10-10 08:22:59,496 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message

2012-10-10 08:22:59,523 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (127.0.0.1)
2012-10-10 08:22:59,540 [0x7fd3e5775700] [DEBUG]: Generated queryID: instanceID=0, time=1349871779, clock=1915432704, nextID=232, queryID=1102776932491
2012-10-10 08:22:59,547 [0x7fd3e5775700] [DEBUG]: Allocating query (1102776932491)
2012-10-10 08:22:59,547 [0x7fd3e5775700] [DEBUG]: Number of allocated queries = 2
2012-10-10 08:22:59,547 [0x7fd3e5775700] [DEBUG]: Initialized query (1102776932491)
2012-10-10 08:22:59,547 [0x7fd3e5775700] [DEBUG]: Parsing query(1102776932491): select count(*) from MerraMonthly
2012-10-10 08:22:59,703 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,704 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,718 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,724 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,745 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator aggregate: not empty MerraMonthly@8<$expr$:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,751 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,751 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator aggregate: not empty MerraMonthly@8<$expr$:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,775 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator apply: not empty MerraMonthly@8<$expr$:uint64 NULL,count:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,775 [0x7fd3e5775700] [DEBUG]: Acquiring 1 array locks for query 1102776932491
2012-10-10 08:22:59,775 [0x7fd3e5775700] [DEBUG]: Acquiring lock: Lock: arrayName=MerraMonthly, arrayId=0, queryId=1102776932491, instanceId=0, instanceRole=COORD, lockMode=1, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-10 08:22:59,776 [0x7fd3e5775700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=MerraMonthly, arrayId=0, queryId=1102776932491, instanceId=0, instanceRole=COORD, lockMode=1, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-10 08:22:59,868 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,869 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,870 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,870 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,870 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator aggregate: not empty MerraMonthly@8<$expr$:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,871 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,871 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator aggregate: not empty MerraMonthly@8<$expr$:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,871 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator apply: not empty MerraMonthly@8<$expr$:uint64 NULL,count:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,872 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator scan: MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
2012-10-10 08:22:59,872 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator aggregate: not empty MerraMonthly@8<$expr$:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,872 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator apply: not empty MerraMonthly@8<$expr$:uint64 NULL,count:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,872 [0x7fd3e5775700] [DEBUG]: Inferred schema for operator project: not empty MerraMonthly@8<count:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:22:59,872 [0x7fd3e5775700] [DEBUG]: The query is prepared
2012-10-10 08:22:59,872 [0x7fd3e5775700] [DEBUG]: The result preparation of query is sent to the client
2012-10-10 08:22:59,873 [0x7fd3e5674700] [DEBUG]: Executing query(1102776932491): select count(*) from MerraMonthly
2012-10-10 08:22:59,873 [0x7fd3e5674700] [DEBUG]: Creating Habilis optimizer instance
2012-10-10 08:22:59,876 [0x7fd3e5674700] [DEBUG]: Query is optimized
2012-10-10 08:22:59,876 [0x7fd3e5674700] [DEBUG]: The physical plan is detected as DML
2012-10-10 08:22:59,876 [0x7fd3e5674700] [DEBUG]: 
[pPlan]:
>[pInstance] physicalProject agg 0 ddl 0 tile 1 children 1
  schema not empty MerraMonthly@8<count:uint64 NULL> [i=0:0,1,0]
  props sgm 1 sgo 1
  distr roro
  bound start [0] end [0] density 1 cells 1 chunks 1 est_bytes 29
>>[pInstance] physicalApply agg 0 ddl 0 tile 1 children 1
   schema not empty MerraMonthly@8<$expr$:uint64 NULL,count:uint64 NULL> [i=0:0,1,0]
   props sgm 1 sgo 1
   distr roro
   bound start [0] end [0] density 1 cells 1 chunks 1 est_bytes 57
>>>[pInstance] physical_aggregate agg 0 ddl 0 tile 1 children 1
    schema not empty MerraMonthly@8<$expr$:uint64 NULL> [i=0:0,1,0]
    props sgm 1 sgo 1
    distr roro
    bound start [0] end [0] density 1 cells 1 chunks 1 est_bytes 29
>>>>[pInstance] physicalScan agg 0 ddl 0 tile 1 children 0
     schema MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
     props sgm 1 sgo 1
     distr roro
     bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 1 cells 25438500360 chunks 768 est_bytes 1.92569e+13

2012-10-10 08:22:59,876 [0x7fd3e5674700] [DEBUG]: (Pre)Single executing queryID: 1102776932491
2012-10-10 08:22:59,877 [0x7fd3e5674700] [DEBUG]: Query is serialized: [pPlan]:
>[pInstance] physicalProject agg 0 ddl 0 tile 1 children 1
  schema not empty MerraMonthly@8<count:uint64 NULL> [i=0:0,1,0]
  props sgm 1 sgo 1
  distr roro
  bound start [0] end [0] density 1 cells 1 chunks 1 est_bytes 29
>>[pInstance] physicalApply agg 0 ddl 0 tile 1 children 1
   schema not empty MerraMonthly@8<$expr$:uint64 NULL,count:uint64 NULL> [i=0:0,1,0]
   props sgm 1 sgo 1
   distr roro
   bound start [0] end [0] density 1 cells 1 chunks 1 est_bytes 57
>>>[pInstance] physical_aggregate agg 0 ddl 0 tile 1 children 1
    schema not empty MerraMonthly@8<$expr$:uint64 NULL> [i=0:0,1,0]
    props sgm 1 sgo 1
    distr roro
    bound start [0] end [0] density 1 cells 1 chunks 1 est_bytes 29
>>>>[pInstance] physicalScan agg 0 ddl 0 tile 1 children 0
     schema MerraMonthly@8<H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [dayMerraMonthly=197701:201007,100,0,heightMerraMonthly=0:41,100,0,xdimMerraMonthly=0:539,100,0,ydimMerraMonthly=0:360,100,0]
     props sgm 1 sgo 1
     distr roro
     bound start [197901, 0, 0, 0] end [201007, 41, 539, 360] density 1 cells 25438500360 chunks 768 est_bytes 1.92569e+13

2012-10-10 08:22:59,877 [0x7fd3e5674700] [DEBUG]: Prepare physical plan was sent out
2012-10-10 08:22:59,877 [0x7fd3e5674700] [DEBUG]: Waiting confirmation about preparing physical plan in queryID from 9 instances
2012-10-10 08:22:59,879 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102776932491 from instance 1
2012-10-10 08:22:59,887 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102776932491 from instance 5
2012-10-10 08:22:59,897 [0x7fd3e5775700] [DEBUG]: Notify on processing query 1102776932491 from instance 2
2012-10-10 08:22:59,924 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102776932491 from instance 9
2012-10-10 08:23:00,034 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-10 08:23:00,034 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (10.0.0.3)
2012-10-10 08:23:00,034 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-10 08:23:00,034 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (10.0.0.4)
2012-10-10 08:23:00,034 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102776932491 from instance 3
2012-10-10 08:23:00,034 [0x7fd3e5775700] [DEBUG]: Notify on processing query 1102776932491 from instance 4
2012-10-10 08:23:00,046 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-10 08:23:00,047 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (10.0.0.7)
2012-10-10 08:23:00,047 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-10 08:23:00,047 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (10.0.0.6)
2012-10-10 08:23:00,047 [0x7fd3ef66a700] [DEBUG]: Notify on processing query 1102776932491 from instance 7
2012-10-10 08:23:00,047 [0x7fd3e5573700] [DEBUG]: Notify on processing query 1102776932491 from instance 6
2012-10-10 08:23:00,114 [0x7fd3e5775700] [DEBUG]: Notify on processing query 1102776932491 from instance 8
2012-10-10 08:23:00,114 [0x7fd3e5674700] [DEBUG]: Execute physical plan was sent out
2012-10-10 08:23:00,114 [0x7fd3e5674700] [INFO ]: Executing query(1102776932491): select count(*) from MerraMonthly
2012-10-10 08:23:00,115 [0x7fd3e5674700] [DEBUG]: Request shared lock of array MerraMonthly@8 for query 1102776932491
2012-10-10 08:23:00,115 [0x7fd3e5674700] [DEBUG]: Granted shared lock of array MerraMonthly@8 for query 1102776932491
2012-10-10 08:23:00,117 [0x7fd3e5674700] [DEBUG]: AggIOMapping input 0 countOnly 1 iterMode 7
2012-10-10 08:23:00,117 [0x7fd3e5674700] [DEBUG]: >>aggregate count outputatt 0 nullbarrier 0 sco 0
2012-10-10 08:23:01,002 [0x7fd3e5674700] [DEBUG]: SG_AGGREGATE started
2012-10-10 08:23:01,271 [0x7fd3e5674700] [DEBUG]: Sending barrier to every one and waiting for 9 barrier messages
2012-10-10 08:23:01,271 [0x7fd3e5674700] [DEBUG]: All barrier messages received - continuing
2012-10-10 08:23:01,287 [0x7fd3e5674700] [DEBUG]: Sending sync to every one and waiting for 9 sync confirmations
2012-10-10 08:23:01,321 [0x7fd3e5674700] [DEBUG]: All confirmations received - continuing
2012-10-10 08:23:01,321 [0x7fd3e5674700] [DEBUG]: Sending barrier to every one and waiting for 9 barrier messages
2012-10-10 08:23:01,321 [0x7fd3e5674700] [DEBUG]: All barrier messages received - continuing
2012-10-10 08:23:01,321 [0x7fd3e5674700] [DEBUG]: Finishing SG_AGGREGATE work; sent 0 bytes.
2012-10-10 08:23:01,322 [0x7fd3e5775700] [DEBUG]: Received query result from instance#1, queryID=1102776932491, arrayName=
<same for #2,5,8,9,3,4,7,6>
2012-10-10 08:23:01,389 [0x7fd3e5674700] [DEBUG]: Query is executed locally
2012-10-10 08:23:01,389 [0x7fd3e5674700] [DEBUG]: The responses are received
2012-10-10 08:23:01,389 [0x7fd3e5674700] [DEBUG]: (Post)Single executing queryID: 1102776932491
2012-10-10 08:23:01,389 [0x7fd3e5674700] [DEBUG]: The result of query is returned
2012-10-10 08:23:01,389 [0x7fd3e5674700] [DEBUG]: The result of query is sent to the client
2012-10-10 08:23:01,440 [0x7fd3ef66a700] [DEBUG]: Query (1102776932491) is committed
2012-10-10 08:23:01,440 [0x7fd3ef66a700] [DEBUG]: Deallocating query (1102776932491)
2012-10-10 08:23:01,440 [0x7fd3ef66a700] [DEBUG]: Releasing locks for query 1102776932491
2012-10-10 08:23:01,440 [0x7fd3ef66a700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1102776932491
2012-10-10 08:23:01,577 [0x7fd3ef66a700] [DEBUG]: Release lock of array MerraMonthly@8 for query 1102776932491
2012-10-10 08:23:01,699 [0x7fd3ef68a7c0] [DEBUG]: Disconnected
2012-10-10 08:23:01,915 [0x7fd3ef68a7c0] [DEBUG]: Waiting for the first message
2012-10-10 08:23:01,915 [0x7fd3ef68a7c0] [DEBUG]: Connection started from CLIENT (127.0.0.1)
2012-10-10 08:23:01,915 [0x7fd3e5573700] [DEBUG]: Generated queryID: instanceID=0, time=1349871781, clock=1915622704, nextID=233, queryID=1102777122494
2012-10-10 08:23:01,915 [0x7fd3e5573700] [DEBUG]: Allocating query (1102777122494)
2012-10-10 08:23:01,915 [0x7fd3e5573700] [DEBUG]: Number of allocated queries = 2
2012-10-10 08:23:01,915 [0x7fd3e5573700] [DEBUG]: Initialized query (1102777122494)
2012-10-10 08:23:01,915 [0x7fd3e5573700] [DEBUG]: Parsing query(1102777122494): select count(*) from MerraRaw
2012-10-10 08:23:01,995 [0x7fd3e5573700] [DEBUG]: Inferred schema for operator scan: MerraRaw@9<day:int64,height:int64,xdim:int64,ydim:int64,H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [LineMerraRaw=0:8187479,1000000,0]
2012-10-10 08:23:01,995 [0x7fd3e5573700] [DEBUG]: Inferred schema for operator scan: 
<above line repeats twice>

MerraRaw@9<day:int64,height:int64,xdim:int64,ydim:int64,H:float,T:float,U:float,V:float,QV:float,O3:float,Cov_U_V:float,Cov_U_T:float,Cov_V_T:float,Cov_U_QV:float,Cov_V_QV:float,vsts:float,Var_H:float,Var_T:float,Var_U:float,Var_V:float,Var_QV:float,Var_O3:float> [LineMerraRaw=0:8187479,1000000,0]
2012-10-10 08:23:01,996 [0x7fd3e5573700] [DEBUG]: Inferred schema for operator aggregate: not empty MerraRaw@9<$expr$:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:23:01,997 [0x7fd3e5573700] [DEBUG]: Inferred schema for operator scan: MerraRaw@9<day:int64,... same as above line ...

2012-10-10 08:23:01,997 [0x7fd3e5573700] [DEBUG]: Inferred schema for operator aggregate: not empty MerraRaw@9<$expr$:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:23:01,997 [0x7fd3e5573700] [DEBUG]: Inferred schema for operator apply: not empty MerraRaw@9<$expr$:uint64 NULL,count:uint64 NULL> [i=0:0,1,0]
2012-10-10 08:23:01,998 [0x7fd3e5573700] [DEBUG]: Acquiring 1 array locks for query 1102777122494
2012-10-10 08:23:01,998 [0x7fd3e5573700] [DEBUG]: Acquiring lock: Lock: arrayName=MerraRaw, arrayId=0, queryId=1102777122494, instanceId=0, instanceRole=COORD, lockMode=1, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-10 08:23:01,998 [0x7fd3e5573700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=MerraRaw, arrayId=0, queryId=1102777122494, instanceId=0, instanceRole=COORD, lockMode=1, arrayVersion=0, arrayVersionId=0, timestamp=1318
2012-10-10 08:23:54,670 [0x7fd3ef68a7c0] [WARN ]: Cancel client query 1102777122494 on disconnect
2012-10-10 08:23:54,670 [0x7fd3e5674700] [DEBUG]: Query (1102777122494) is being aborted
2012-10-10 08:23:54,670 [0x7fd3e5674700] [DEBUG]: Query (1102777122494) is still in progress
2012-10-10 08:23:56,065 [0x7fd3e5573700] [DEBUG]: Releasing locks for query 1102777122494
2012-10-10 08:23:56,065 [0x7fd3e5573700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1102777122494
2012-10-10 08:23:56,066 [0x7fd3e5573700] [DEBUG]: Query::done: queryID=1102777122494, _commitState=2, erorCode=62
2012-10-10 08:23:56,066 [0x7fd3e5573700] [DEBUG]: Query (1102777122494) is being aborted
2012-10-10 08:23:56,066 [0x7fd3e5573700] [DEBUG]: Deallocating query (1102777122494)
2012-10-10 08:23:56,066 [0x7fd3e5573700] [DEBUG]: Releasing locks for query 1102777122494
2012-10-10 08:23:56,066 [0x7fd3e5573700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1102777122494
2012-10-10 08:23:56,066 [0x7fd3e5573700] [ERROR]: prepareClientQuery failed to complete: SystemException in file: src/query/Query.cpp function: handleAbort line: 527
Error id: scidb::SCIDB_SE_QPROC::SCIDB_LE_QUERY_CANCELLED
Error description: Query processor error. Query 1102777122494 was cancelled.
2012-10-10 08:23:56,066 [0x7fd3e5573700] [DEBUG]: Query 1102777122494 is not found
2012-10-10 08:23:56,067 [0x7fd3e5573700] [DEBUG]: Disconnected
local $ 

Any hints? -George


#2

For what it’s worth, all the fsync errors seem to be related to instance 1 (there are 1-9)
I checked instance 1 host, and saw nothing violently wrong …

However: what if my chunksize is too big? I’ve been avoiding making them too small…
Could it be, that if my chunksize is too big, then instance 1 gets hammered while the rest are starved?

I tried the load of one file with a smaller chunk and I still get the ‘Operation fsync failed’

I ran my very small-scale test again that worked fine. The small scale test uses only stacks of 3x3 matrices just to test the load and merge logic…

George


#3

George, thank you very much for telling us this.
Earlier you wrote in a different post that you’re rerunning this on 12.7. Did that work at all?

We never saw this error before. I am not sure what could cause it. The only possibilities I can think of are:

  • a genuine disk error (a bad sector somewhere)
  • running out of space on disk

Have you checked disk space, i.e. “df -h” ?
Do you have a file that deterministically reproduces this?
Does it always happen on the same file or does it happen after you load a particular amount of data?
Have you checked the sizes of the storage.header and storage.data1 files on instance1? Anything out of the ordinary?

Please keep me posted.


#4

On “instance 1” server:

[code]$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/visor01-root 226G 144G 71G 67% /
udev 3.8G 4.0K 3.8G 1% /dev
tmpfs 1.6G 456K 1.6G 1% /run
none 5.0M 0 5.0M 0% /run/lock
none 3.9G 0 3.9G 0% /run/shm
/dev/sda1 228M 70M 146M 33% /boot
10.0.0.15:/opt/scidb 227G 33G 183G 15% /opt/scidb
10.0.0.12:/home 917G 9.5G 861G 2% /home
10.0.0.12:/usr/local/other 917G 9.1G 862G 2% /usr/local/other
/dev/md2 917G 3.4G 868G 1% /bigdata

[/code]
On the coordinator:

Filesystem Size Used Avail Use% Mounted on /dev/mapper/visor10-root 227G 33G 183G 15% / udev 3.4G 4.0K 3.4G 1% /dev tmpfs 1.4G 324K 1.4G 1% /run none 5.0M 0 5.0M 0% /run/lock none 3.4G 0 3.4G 0% /run/shm /dev/sda1 228M 70M 146M 33% /boot 169.154.148.23:/raid0/data/merra 4.4T 1.4T 3.1T 31% /merra scidb@hadoop15:~/projects$

I use /bigdata on all instances to root the scidb/merra data store. Each /bigdata on each server is local
(The coordinator doesn’t have a separate /bigdata, it is simply under / )

When I switched to 12.7 from 12.3, total load times for all thee phases went from 20 minutes to about 10 on the average
Reminder: phase1-3 are as follows

  1. generate ascii csv from HDF-EOS files and pipe them to csv2scidb which writes it to /tmp/load_pipe
    at the same time, AFL load(MerraRaw, ‘/tmp/load_pipe’)

  2. redimension: load temp from MerraRaw that turns oneD into fourD (height, lat, lon, time)
    AQL: select * into temp from MerraRaw;

  3. merge with master array: AFL store(merge( temp, MerraMonthly ), MerraMonthly)

Storage file sizes, coordinator:

-rwxrwxr-x 1 scidb scidb 3551150472 Oct 11 08:59 storage.data1 -rwxrwxr-x 1 scidb scidb 876360 Oct 11 09:17 storage.header -rwxrwxr-x 1 scidb scidb 431184 Oct 11 08:59 storage.log_1 -rwxrwxr-x 1 scidb scidb 0 Oct 10 17:39 storage.log_2
and instance 1:

-rwxrwxr-x 1 scidb scidb 3341483764 Oct 11 08:56 storage.data1 -rwxrwxr-x 1 scidb scidb 877216 Oct 11 09:20 storage.header -rwxrwxr-x 1 scidb scidb 416936 Oct 11 08:56 storage.log_1 -rwxrwxr-x 1 scidb scidb 0 Oct 10 17:39 storage.log_2

Anything weird looking?

Cheers, George