[MCOL-2187] more verbose error messasge for cpimport with importfile with too many columns Created: 2019-02-21  Updated: 2021-05-02  Resolved: 2019-04-23

Status: Closed
Project: MariaDB ColumnStore
Component/s: cpimport
Affects Version/s: 1.0.0, 1.2
Fix Version/s: Icebox

Type: New Feature Priority: Major
Reporter: Richard Stracke Assignee: Richard Stracke
Resolution: Not a Bug Votes: 0
Labels: None


 Description   

To reproduce

create table t1 (a int) engine=columnstore;

Create inputfile b1.txt

5,5,5
3,3,5
1,2,7

Creeate the job

./colxml test -j10007 -d"," -e1 -l"/b1.txt" -tt1 -b3

Run the job

cpimport -j10007

Job failed, but with no obvious reason.
We know, it it caused by too many columns in the inputfile (3 instead 1 in this case)

Input file(s) will be read from Bulkload root directory : /usr/local/mariadb/columnstore/data/bulk
Job description file : /usr/local/mariadb/columnstore/data/bulk/job/Job_10007.xml
Log file for this job: /usr/local/mariadb/columnstore/data/bulk/log/Job_10007.log
2019-02-21 14:43:22 (5476) INFO : successfully loaded job file /usr/local/mariadb/columnstore/data/bulk/job/Job_10007.xml
2019-02-21 14:43:22 (5476) INFO : Job file loaded, run time for this step : 0.0468609 seconds
2019-02-21 14:43:22 (5476) INFO : PreProcessing check starts
2019-02-21 14:43:22 (5476) INFO : input data file /b1.txt
2019-02-21 14:43:22 (5476) INFO : PreProcessing check completed
2019-02-21 14:43:22 (5476) INFO : preProcess completed, run time for this step : 0.00511003 seconds
2019-02-21 14:43:22 (5476) INFO : No of Read Threads Spawned = 1
2019-02-21 14:43:22 (5476) INFO : No of Parse Threads Spawned = 3
2019-02-21 14:43:22 (5476) INFO : Number of rows with errors = 2.  Row numbers with error reasons are listed in file /b1.txt.Job_10007_5476.err
2019-02-21 14:43:22 (5476) INFO : Number of rows with errors = 2.  Exact error rows are listed in file /b1.txt.Job_10007_5476.bad
2019-02-21 14:43:22 (5476) ERR  : Actual error row count(2) exceeds the max error rows(1) allowed for table test.t1 [1451]
2019-02-21 14:43:22 (5476) CRIT : Bulkload Read (thread 0) Failed for Table test.t1.  Terminating this job. [1451]
2019-02-21 14:43:22 (5476) INFO : Bulkload Parse (thread 0) Stopped parsing Tables. BulkLoad::parse() responding to job termination
2019-02-21 14:43:22 (5476) INFO : Bulkload Parse (thread 2) Stopped parsing Tables. BulkLoad::parse() responding to job termination
2019-02-21 14:43:22 (5476) INFO : Bulkload Parse (thread 1) Stopped parsing Tables. BulkLoad::parse() responding to job termination
2019-02-21 14:43:23 (5476) INFO : Table test.t1 (OID-3000) was not successfully loaded.  Rolling back.
2019-02-21 14:43:23 (5476) INFO : Bulk load completed, total run time : 1.07283 seconds

Also the bulkload logfile is not very informative

[root@3329b9a3b65a log]# cat Job_10007.err
2019-02-21 14:43:22 (5476) ERR  : Actual error row count(2) exceeds the max error rows(1) allowed for table test.t1 [1451]
2019-02-21 14:43:22 (5476) CRIT : Bulkload Read (thread 0) Failed for Table test.t1.  Terminating this job. [1451]
[root@3329b9a3b65a log]# cat Job_10007.log
2019-02-21 14:43:22 (5476) INFO2 : Locale is : C
2019-02-21 14:43:22 (5476) INFO : successfully loaded job file /usr/local/mariadb/columnstore/data/bulk/job/Job_10007.xml
2019-02-21 14:43:22 (5476) INFO2 : Command line options: -j 10007 -P pm1-5476 -uf6c5bca2-4a30-40c3-b2a2-7955ee3e06a3 
2019-02-21 14:43:22 (5476) INFO : Job file loaded, run time for this step : 0.0468609 seconds
2019-02-21 14:43:22 (5476) INFO2 : XMLJobFile: Delim(,); EnclosedBy(n/a); EscapeChar(\); ReadBufs(5); ReadBufSize(1048576); setvbufSize(10485760)
2019-02-21 14:43:22 (5476) INFO2 :   Table(test.t1); OID(3000); MaxErrNum(1)
2019-02-21 14:43:22 (5476) INFO2 :     Column(a); OID(3001); Type(integer); Width(4); Comp(2)
2019-02-21 14:43:22 (5476) INFO : PreProcessing check starts
2019-02-21 14:43:22 (5476) INFO : input data file /b1.txt
2019-02-21 14:43:22 (5476) INFO2 : Starting DBRoot info for OID 3001
  DBRoot-1, part/seg/hwm/LBID/totBlks/state: 0/0/0/234496/1/PartialExtent
2019-02-21 14:43:22 (5476) INFO2 : Selecting existing segFile to begin adding rows: oid-3001; DBRoot-1, part/seg/hwm/LBID/totBlks/state: 0/0/0/234496/1/PartialExtent
2019-02-21 14:43:22 (5476) INFO2 : Initializing import: Table-test.t1...
2019-02-21 14:43:22 (5476) INFO2 : Backing up HWM chunk for column OID-3001; file-/usr/local/mariadb/columnstore/data1/bulkRollback/3000_data/3001.p0.s0.tmp; HWM-0; bytes-65536; fileSize-1056768
2019-02-21 14:43:22 (5476) INFO2 : Initializing import: Table-test.t1; Col-a (compressed); OID-3001; hwm-1; file-/usr/local/mariadb/columnstore/data1/000.dir/000.dir/011.dir/185.dir/000.dir/FILE000.cdf
2019-02-21 14:43:22 (5476) INFO : PreProcessing check completed
2019-02-21 14:43:22 (5476) INFO : preProcess completed, run time for this step : 0.00511003 seconds
2019-02-21 14:43:22 (5476) INFO : No of Read Threads Spawned = 1
2019-02-21 14:43:22 (5476) INFO2 : Opening /b1.txt to import into table test.t1
2019-02-21 14:43:22 (5476) INFO2 : Start reading and loading table test.t1
2019-02-21 14:43:22 (5476) INFO : No of Parse Threads Spawned = 3
2019-02-21 14:43:22 (5476) INFO : Number of rows with errors = 2.  Row numbers with error reasons are listed in file /b1.txt.Job_10007_5476.err
2019-02-21 14:43:22 (5476) INFO : Number of rows with errors = 2.  Exact error rows are listed in file /b1.txt.Job_10007_5476.bad
2019-02-21 14:43:22 (5476) ERR  : Actual error row count(2) exceeds the max error rows(1) allowed for table test.t1 [1451]
2019-02-21 14:43:22 (5476) CRIT : Bulkload Read (thread 0) Failed for Table test.t1.  Terminating this job. [1451]
2019-02-21 14:43:22 (5476) INFO : Bulkload Parse (thread 0) Stopped parsing Tables. BulkLoad::parse() responding to job termination
2019-02-21 14:43:22 (5476) INFO : Bulkload Parse (thread 2) Stopped parsing Tables. BulkLoad::parse() responding to job termination
2019-02-21 14:43:22 (5476) INFO : Bulkload Parse (thread 1) Stopped parsing Tables. BulkLoad::parse() responding to job termination
2019-02-21 14:43:23 (5476) INFO : Table test.t1 (OID-3000) was not successfully loaded.  Rolling back.
2019-02-21 14:43:23 (5476) INFO2 : Closing DB files for table test.t1, left open by abnormal termination.
2019-02-21 14:43:23 (5476) INFO2 : Closing DB column file for: a (OID-3001)
2019-02-21 14:43:23 (5476) INFO2 : Starting bulk rollback for table test.t1 (OID-3000, Lock-5) in cpimport.bin
2019-02-21 14:43:23 (5476) INFO2 : Rolling back extents for table test.t1 (OID-3000)
2019-02-21 14:43:23 (5476) INFO2 : Rolling back extents for table test.t1 (OID-3000); column 3001; DBRoot-1 (column extent)
2019-02-21 14:43:23 (5476) INFO2 : Rolling back extent map for table test.t1 (OID-3000); column 3001; Restoring HWM column extent: dbRoot-1; part#-0; seg#-0; hwm-0
2019-02-21 14:43:23 (5476) INFO2 : Rolling back db file for table test.t1 (OID-3000); column 3001; Reinit HWM compressed column extent in db file: dbRoot-1; part#-0; seg#-0; rawOffset(bytes)-8192; rawFreeBlks-4095
2019-02-21 14:43:23 (5476) INFO2 : Rolling back db file for table test.t1 (OID-3000); column 3001; HWM compressed column file: dbRoot-1; part#-0; seg#-0; rawFreeBlks-127 (abbrev); restoredChunk-65536 bytes; truncated to 1056768 bytes
2019-02-21 14:43:23 (5476) INFO2 : Ending bulk rollback for table test.t1 (OID-3000, Lock-5) in cpimport.bin
2019-02-21 14:43:23 (5476) INFO : Bulk load completed, total run time : 1.07283 seconds



 Comments   
Comment by Andrew Hutchings (Inactive) [ 2019-04-04 ]

You already have that in: /b1.txt.Job_10007_5476.err and /b1.txt.Job_10007_5476.bad. What additional information do you need?

Comment by Richard Stracke [ 2019-04-23 ]

Information are already sufficient

Generated at Thu Feb 08 02:34:23 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.