Details
-
Bug
-
Resolution: Not a Bug
-
Major
-
Columnar 1.0.0
-
Columnar Edition 1.0.0 build 2126
-
Untriaged
-
0
-
Unknown
Description
The system test was run with 50 remote datasets each ingesting 10 mil items. The doc size is between 1.5 KB and 2 KB. Ingestion appears to be slow. It's been almost 5 hours and the ingestion is still not complete. The progress seen as of now -
{
|
"links": [ |
{
|
"name": "linkqvJUoesw", |
"status": "healthy", |
"state": [ |
{
|
"timestamp": 1717599570997, |
"progress": 1.0, |
"scopes": [ |
{
|
"collections": [ |
{
|
"name": "remotedatasetaDIRcxpm" |
},
|
{
|
"name": "remotedatasetyIHaFJAP" |
}
|
],
|
"name": "scope1dqsugHIM" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetmcLvCSMY" |
},
|
{
|
"name": "remotedatasetjMoUTfuN" |
}
|
],
|
"name": "scope0GOGEDQtm" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetvEoLMyOy" |
},
|
{
|
"name": "remotedatasetNhKMFHuN" |
}
|
],
|
"name": "scope1QCcgteJK" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetXggIaKUr" |
}
|
],
|
"name": "scope1lrXRPpsi" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetfvxMoJEX" |
}
|
],
|
"name": "scope0WDytWTpM" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetvOHrDavR" |
}
|
],
|
"name": "scope1gPxGGIek" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetnqYIPTrq" |
}
|
],
|
"name": "scope0qKEiBUtj" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetpIBHqvfp" |
}
|
],
|
"name": "scope1sfhVYNAE" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetGmWscdhm" |
}
|
],
|
"name": "scope1fNbnCggZ" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetnJHVDLzz" |
}
|
],
|
"name": "scope0zqRxsiyX" |
}
|
]
|
}
|
]
|
},
|
{
|
"name": "linkTvXUzluG", |
"status": "healthy", |
"state": [ |
{
|
"timestamp": 1717599570967, |
"progress": 0.5254639, |
"itemsProcessed": 5254639, |
"seqnoAdvances": 4819460, |
"scopes": [ |
{
|
"collections": [ |
{
|
"name": "remotedatasetYLPTAaPH" |
}
|
],
|
"name": "scope1SNkVUOZO" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetYRyeBJov" |
}
|
],
|
"name": "scope0JMMmOBWG" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetdZavqilB" |
}
|
],
|
"name": "scope1wqVnpwJK" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetUixMovfA" |
}
|
],
|
"name": "scope1sfhVYNAE" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetwuJUDOgE" |
}
|
],
|
"name": "scope1lbYMFXFl" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetdOzNuVIj" |
}
|
],
|
"name": "scope0lKYRbKuL" |
}
|
]
|
},
|
{
|
"timestamp": 1717599570967, |
"progress": 1.0, |
"scopes": [ |
{
|
"collections": [ |
{
|
"name": "remotedatasetalCVKIrj" |
}
|
],
|
"name": "scope1dqsugHIM" |
}
|
]
|
},
|
{
|
"timestamp": 1717599570967, |
"progress": 0.5041247, |
"itemsProcessed": 5041247, |
"seqnoAdvances": 59909213, |
"scopes": [ |
{
|
"collections": [ |
{
|
"name": "remotedatasethVXfLAZu" |
}
|
],
|
"name": "scope1UMKjAwGw" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetohTMGTyE" |
}
|
],
|
"name": "scope0lKYRbKuL" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetsJccscCv" |
}
|
],
|
"name": "scope0WDytWTpM" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetxKlPVlmK" |
}
|
],
|
"name": "scope1lrXRPpsi" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetdybfXYbi" |
}
|
],
|
"name": "scope1mtADVgPF" |
}
|
]
|
}
|
]
|
},
|
{
|
"name": "linkbicKdmcC", |
"status": "healthy", |
"state": [ |
{
|
"timestamp": 1717599570979, |
"progress": 0.9321129, |
"itemsProcessed": 9321129, |
"seqnoAdvances": 92434678, |
"scopes": [ |
{
|
"collections": [ |
{
|
"name": "remotedatasetVtyVXAFz" |
}
|
],
|
"name": "scope1WYZjauCJ" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetoJjCIRZH" |
}
|
],
|
"name": "scope0kozGLoEX" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetMffrzXpU" |
}
|
],
|
"name": "scope1hddgoMXe" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetxOSNmYhz" |
}
|
],
|
"name": "scope0jfeDPikd" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetECzjdwov" |
}
|
],
|
"name": "scope1lbYMFXFl" |
}
|
]
|
},
|
{
|
"timestamp": 1717599570979, |
"progress": 0.9090909533949946, |
"itemsProcessed": 13057767, |
"seqnoAdvances": 97634934, |
"scopes": [ |
{
|
"collections": [ |
{
|
"name": "remotedatasetBQNRlrCD" |
},
|
{
|
"name": "remotedatasetKEOKoMyy" |
}
|
],
|
"name": "scope0GOGEDQtm" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetXLpCGoHr" |
}
|
],
|
"name": "scope1zPJEZWNU" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetDQwhKrJF" |
},
|
{
|
"name": "remotedatasetyCWRYkNm" |
}
|
],
|
"name": "scope1gPxGGIek" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetNUCxnYCW" |
}
|
],
|
"name": "scope1UMKjAwGw" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetZhVAZaHq" |
}
|
],
|
"name": "scope0lKYRbKuL" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetlkeaVjLq" |
}
|
],
|
"name": "scope1wqVnpwJK" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetMXGCCMKb" |
}
|
],
|
"name": "scope0UgFKeYYs" |
}
|
]
|
}
|
]
|
},
|
{
|
"name": "linklUbLQsth", |
"status": "healthy", |
"state": [ |
{
|
"timestamp": 1717599571000, |
"progress": 1.0, |
"scopes": [ |
{
|
"collections": [ |
{
|
"name": "remotedatasetxHuantMq" |
}
|
],
|
"name": "scope1QCcgteJK" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetiNvlQuUr" |
},
|
{
|
"name": "remotedatasettzyYjiNu" |
}
|
],
|
"name": "scope0jfeDPikd" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetRAmJZxLK" |
}
|
],
|
"name": "scope0ffJiSGtL" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetqvXmOrSu" |
},
|
{
|
"name": "remotedatasetdvpPKvCD" |
}
|
],
|
"name": "scope0dXuMHGUZ" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetPllwYeCx" |
}
|
],
|
"name": "scope1dqsugHIM" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetjOzSqGQE" |
}
|
],
|
"name": "scope0GOGEDQtm" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetyjdNZuSw" |
}
|
],
|
"name": "scope1wsioFnVF" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetLJaYMvwg" |
}
|
],
|
"name": "scope0RgeZRJim" |
},
|
{
|
"collections": [ |
{
|
"name": "remotedatasetCjVtByER" |
}
|
],
|
"name": "scope0gzkeiTTb" |
}
|
]
|
}
|
]
|
}
|
]
|
}
|
|
|
As seen on 002 - |
I am not really sure if these are relevant to slow ingestion, but I see a bunch of exceptions in the log .
2024-06-05T11:58:25.627+00:00 INFO CBAS.servlet.LowCardinalityStatsApiServlet [HttpExecutor(port:9110)-14] exception thrown for com.couchbase.analytics.request.AnalyticsServletRequest@3728e8dc |
java.io.UncheckedIOException: java.nio.file.NoSuchFileException: /var/cb-cache/@analytics/v_iodevice_3/storage/partition_115/Database7UOLucXPf/scope1UMKjAwGw/remotedatasetNUCxnYCW/0/remotedatasetNUCxnYCW/70_70_b.dic |
at org.apache.commons.io.function.Uncheck.wrap(Uncheck.java:339) ~[commons-io-2.15.1.jar:2.15.1] |
at org.apache.commons.io.function.Uncheck.get(Uncheck.java:199) ~[commons-io-2.15.1.jar:2.15.1] |
at org.apache.commons.io.FileUtils.sizeOfDirectory(FileUtils.java:2947) ~[commons-io-2.15.1.jar:2.15.1] |
at org.apache.hyracks.control.nc.io.IOManager.getTotalDiskUsage(IOManager.java:476) ~[hyracks-control-nc.jar:1.0.0-2126] |
at org.apache.hyracks.util.cache.CacheableValue.cache(CacheableValue.java:41) ~[hyracks-util.jar:1.0.0-2126] |
at org.apache.hyracks.util.cache.CacheManager.get(CacheManager.java:45) ~[hyracks-util.jar:1.0.0-2126] |
at com.couchbase.analytics.servlet.LowCardinalityStatsApiServlet.get(LowCardinalityStatsApiServlet.java:262) [columnar-server.jar:1.0.0-2126] |
at org.apache.hyracks.http.server.AbstractServlet.handle(AbstractServlet.java:90) [hyracks-http.jar:1.0.0-2126] |
at com.couchbase.analytics.servlet.AuthenticatedServlet.handle(AuthenticatedServlet.java:96) [columnar-server.jar:1.0.0-2126] |
at org.apache.hyracks.http.server.HttpRequestHandler.handle(HttpRequestHandler.java:83) [hyracks-http.jar:1.0.0-2126] |
at org.apache.hyracks.http.server.HttpRequestHandler.call(HttpRequestHandler.java:68) [hyracks-http.jar:1.0.0-2126] |
at org.apache.hyracks.http.server.HttpRequestHandler.call(HttpRequestHandler.java:37) [hyracks-http.jar:1.0.0-2126] |
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] |
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?] |
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?] |
at java.base/java.lang.Thread.run(Thread.java:840) [?:?] |
Caused by: java.nio.file.NoSuchFileException: /var/cb-cache/@analytics/v_iodevice_3/storage/partition_115/Database7UOLucXPf/scope1UMKjAwGw/remotedatasetNUCxnYCW/0/remotedatasetNUCxnYCW/70_70_b.dic |
at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92) ~[?:?] |
at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:106) ~[?:?] |
at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111) ~[?:?] |
at java.base/sun.nio.fs.UnixFileAttributeViews$Basic.readAttributes(UnixFileAttributeViews.java:55) ~[?:?] |
at java.base/sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:148) ~[?:?] |
at java.base/sun.nio.fs.LinuxFileSystemProvider.readAttributes(LinuxFileSystemProvider.java:99) ~[?:?] |
at java.base/java.nio.file.Files.readAttributes(Files.java:1851) ~[?:?] |
at java.base/java.nio.file.FileTreeWalker.getAttributes(FileTreeWalker.java:220) ~[?:?] |
at java.base/java.nio.file.FileTreeWalker.visit(FileTreeWalker.java:277) ~[?:?] |
at java.base/java.nio.file.FileTreeWalker.next(FileTreeWalker.java:374) ~[?:?] |
at java.base/java.nio.file.Files.walkFileTree(Files.java:2845) ~[?:?] |
at java.base/java.nio.file.Files.walkFileTree(Files.java:2882) ~[?:?] |
at org.apache.commons.io.file.PathUtils.visitFileTree(PathUtils.java:1653) ~[commons-io-2.15.1.jar:2.15.1] |
at org.apache.commons.io.file.PathUtils.countDirectory(PathUtils.java:349) ~[commons-io-2.15.1.jar:2.15.1] |
at org.apache.commons.io.file.PathUtils.sizeOfDirectory(PathUtils.java:1591) ~[commons-io-2.15.1.jar:2.15.1] |
at org.apache.commons.io.FileUtils.lambda$sizeOfDirectory$15(FileUtils.java:2947) ~[commons-io-2.15.1.jar:2.15.1] |
at org.apache.commons.io.function.Uncheck.get(Uncheck.java:197) ~[commons-io-2.15.1.jar:2.15.1] |
... 14 more |
Another example of slowness was that copy into statement took a long time (over 1.5 hours).
{
|
"cancellable": true, |
"clientContextID": null, |
"elapsedTime": "6322.757s", |
"jobCreateTime": "2024-06-05T12:40:46.828", |
"jobEndTime": "2024-06-05T14:26:08.693", |
"jobId": "JID:0.283", |
"jobQueueTime": 0, |
"jobRequiredCPUs": 32, |
"jobRequiredMemory": 82575360, |
"jobStartTime": "2024-06-05T12:40:46.828", |
"jobStatus": "TERMINATED", |
"node": "10.0.23.102:18095", |
"remoteAddr": "44.211.20.177:38328", |
"requestTime": "2024-06-05T12:40:46.170", |
"scanConsistency": "not_bounded", |
"state": "completed", |
"statement": "COPY INTO `Database22xVgGwuwu`.`scope0jwVzaVzh`.`standaloneGCWXJmIg` AS (id int,product_name string,product_link string, product_features string,product_specs string, product_image_links string,product_reviews string, product_category string, price double,avg_rating double, num_sold int,upload_date string,weight double,quantity int, seller_name string, seller_location string,seller_verified boolean,template_name string,mutated int, padding string) FROM `columnar-functional-sanity-test-data` AT `avroExternalLinkLSOEqejZTY` PATH \"\" WITH {\"format\":\"csv\",\"header\":\"true\",\"include\":[\"*file_2*.csv\"]};", |
"userAgent": "Go-http-client/1.1", |
"users": "MAE1CeleJMq1Sw8GxGIiDsfqGeIfQDXk", |
"uuid": "065e747c-98fc-4033-b948-2975173c43ec" |
}
|
The same statement took a much shorter time on executing the second time -
{
|
"cancellable": true, |
"clientContextID": null, |
"elapsedTime": "5674.381s", |
"jobCreateTime": "2024-06-05T14:26:09.531", |
"jobEndTime": "2024-06-05T14:45:20.421", |
"jobId": "JID:0.499", |
"jobQueueTime": 0, |
"jobRequiredCPUs": 32, |
"jobRequiredMemory": 82575360, |
"jobStartTime": "2024-06-05T14:26:09.531", |
"jobStatus": "TERMINATED", |
"node": "10.0.18.254:18095", |
"remoteAddr": "44.211.20.177:14584", |
"requestTime": "2024-06-05T13:10:46.797", |
"scanConsistency": "not_bounded", |
"state": "completed", |
"statement": "COPY INTO `Database22xVgGwuwu`.`scope0jwVzaVzh`.`standaloneGCWXJmIg` AS (id int,product_name string,product_link string, product_features string,product_specs string, product_image_links string,product_reviews string, product_category string, price double,avg_rating double, num_sold int,upload_date string,weight double,quantity int, seller_name string, seller_location string,seller_verified boolean,template_name string,mutated int, padding string) FROM `columnar-functional-sanity-test-data` AT `avroExternalLinkLSOEqejZTY` PATH \"\" WITH {\"format\":\"csv\",\"header\":\"true\",\"include\":[\"*file_2*.csv\"]};", |
"userAgent": "Go-http-client/1.1", |
"users": "MAE1CeleJMq1Sw8GxGIiDsfqGeIfQDXk", |
"uuid": "41813b4d-1737-4247-a57b-43af87658a83" |
}
|
The file only has around 8 million items, so seems a little strange for it to be taking this long. It was much quicker when I was running the test on a smaller scale.
There's nothing alarming in the resources used. (I've attached a screenshot of the dashboard).
cbcollect ->
https://cb-engineering.s3.amazonaws.com/SysTestColumnarJun5/collectinfo-2024-06-05T141350-ns_1%40svc-da-node-001.ojc8vwsi23xsigjw.sandbox.nonprod-project-avengers.com.zip
https://cb-engineering.s3.amazonaws.com/SysTestColumnarJun5/collectinfo-2024-06-05T141350-ns_1%40svc-da-node-002.ojc8vwsi23xsigjw.sandbox.nonprod-project-avengers.com.zip
