Rename Simvue class

At the moment there's a class called Simvue which is used for creating runs. Since we want to be able to run queries etc from the client as well it would make sense to rename the existing class to something more suitable, e.g. to Run perhaps. So to create a run you'd use:
from simvue import Run

run = Run()
run.init()
...

The existing couple of methods related to download data etc should be moved into a new class.

Yes, that would make more sense. Will make it more structured and easier to test as well.

As well as renaming the existing Simvue class as Run, should move the following methods into a new class, perhaps called Client:

list_artifacts
get_artifact_as_file
get_artifacts_as_files

(The names include as_file because I want to have other versions which don't save to a file, e.g. for a numpy array you could just directly create a variable containing the contents of the artifact).

Implemented in https://github.com/simvue-io/client/commit/db3bde87868bbdd3e8be602cb9638db07076f267


Trying to Run an Exile Server I get this

attached is the problem I get when trying to launch my server
problem.txt

you need to lowercase your mod folder
convert all your mod folders and contents to lower case..
#find . -depth -exec rename 's/(.*)\/([^\/]*)/$1\/\L$2/' {} \;
https://community.bistudio.com/wiki/Arma_3_Dedicated_Server#Case_sensitivity_.26_Mods

"-cfg=/home/arma3server/serverfiles/cfg/Bandit Punisher Exile.network.cfg "
Very bad idea to put spaces in filenames.
And very bad idea to use uppercase addons for any game under linux.

I guess we can close as it's a non script issue, but feel free to re-open the issue if you feel like it's needed. Please note that non script issues are preferably discussed on the steam group in the general support section https://steamcommunity.com/groups/linuxgsm/discussions


Pathway for Contributing

@chrisns I love that you're building this - will be so useful for facilitating cloud migration conversations!
Not sure of where you want to take this in the long run, but I imagine there are some things that you / core team might want to steer (e.g. questions to ask, centrally-agreed framework for migration, etc) but there may be some issues that others in the community can help with (UI components, bugfixes, case-studies / contact deets for improvements in each section).
Some suggestions:

contributing.md guidance
contributor-friendly issues
vision
roadmap
perhaps a CDDO github project

Essentially a way to know the intent, and contribute to the direction.

I'll reach out directly out of band for a chat
right now I want to develop the bare minimum MVP to test this with some departments, to see if its vaguely useful as part of an alpha phase.
after that has at least done its first round I'll be a bit more confident to set vision/roadmap and feel like contributions would have any longevity and the insights I gain wouldn't upset any external contributors by deleting any of their hard work.


kathara/base: Operation not permitted

Hi all,
Thank you for the project.
I am interested in the plugin "kathara/katharanp:amd64". So, I did the following:
sudo touch /var/run/xtables.lock
docker plugin install kathara/katharanp:amd64 xtables_lock.source="/var/run/xtables.lock"   # I granted the privileges
docker network create --driver=kathara/katharanp:amd64 --ipam-driver=null l2net
Then, I created a host/container based on alpine with:
docker container run -it --rm --name a01 --hostname a01 --network l2net alpine
When, I am inside the Alpine container, I can view the information of the interfaces with the following command. I can see "lo" and "eth0". Interface eth0 does not have an IP address as expected.
ifconfig
When I try to assign an IP address with:
ifconfig eth0 <IP_ADDRESS> netmask <IP_ADDRESS>
I get the following error. Any idea what is passing?
ifconfig: SIOCSIFADDR: Operation not permitted
Thank you.

Hi @egamess,
thanks for using our network plugin.
I think that your problem is related to how you start the container. In particular, in order to change interfaces' configurations, the container should have some additional capabilities. In Kathará, we start containers with the following ones:

NET_ADMIN
NET_RAW
NET_BROADCAST
NET_BIND_SERVICE
SYS_ADMIN

You can also do it manually from the command line:
docker container run -it --rm --name a01 --hostname a01 --network l2net --cap-add NET_ADMIN --cap-add NET_RAW --cap-add NET_BROADCAST --cap-add NET_BIND_SERVICE --cap-add SYS_ADMIN alpine

Also, I see that you manually created and mounted the xtables.lock file, but using this file depends on the iptables version that you are using. You can check it by running:
sudo iptables -nvL

If the version is legacy you need the lock file and also to mount it while installing the network plugin. If the version is nf_tables you do not need to manually create the lock file, and also you have to remove the mount instruction (xtables_lock.source="/var/run/xtables.lock") while installing the plugin.
If you need further help, do not hesitate to reply to this issue!
Mariano.

Hello @Skazza94,
Thank you so much for your quick response. Yes, the "capabilities" were missing in my case. This solved the issue. Amazing project.


A query took >20 minutes to finish.

The table ('trips') in my test has 0.5B rows. Somehow MapD takes >20 minutes to finish the following query:
$ time echo "select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);" | /mnt/mapd-core/bin/mapdql ma
pd     -u $MAPD_USERNAME     -p $MAPD_PASSWORD
User mapd connected to database mapd
EXPR$0
1
User mapd disconnected from database mapd

real	21m20.315s
user	0m0.008s
sys	0m0.000s

With the same number of rows on the same machine, another database finished it in 4 minutes, so it shouldn't take >4 minutes to read the two related columns (pickup_datetime and medallion) of the 0.5B rows from disk into cpu memory.
Please share any idea about how i can improve the query performance. Thanks.

Please include the full log from each of the runs so we can help diagnose your issue.

@dwayneberry Here you go.
cat /mnt/trip/mapd/data/mapd_log/mapd_server.INFO
Log file created at: 2017/10/04 23:47:40
Running on machine: osboxes
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I1004 23:47:40.843778 12241 MapDServer.cpp:504] MapD started with data directory at '/mnt/trip/mapd/data'
I1004 23:47:40.893003 12241 MapDServer.cpp:511]  Watchdog is set to 1
I1004 23:47:40.893019 12241 MapDServer.cpp:533]  cuda block size 0
I1004 23:47:40.893026 12241 MapDServer.cpp:534]  cuda grid size  0
I1004 23:47:40.893029 12241 MapDServer.cpp:535]  calcite JVM max memory  1024
I1004 23:47:40.893033 12241 MapDServer.cpp:536]  MapD Server Port  9091
I1004 23:47:40.893038 12241 MapDServer.cpp:537]  MapD Calcite Port  9093
I1004 23:47:40.893069 12241 MapDHandler.cpp:133] MapD Server 3.3.1dev-20171002-b876cd7
E1004 23:47:40.893075 12241 MapDHandler.cpp:140] This build isn't CUDA enabled, will run on CPU
I1004 23:47:41.051996 12241 DataMgr.cpp:120] cpuSlabSize is 4096M
I1004 23:47:41.052139 12241 FileMgr.cpp:116] Read table metadata, Epoch is 0 for table data at '/mnt/trip/mapd/data/mapd_data/table_0_0/'
I1004 23:47:41.052494 12241 Calcite.cpp:156] Creating Calcite Handler,  Calcite Port is 9093 base data dir is /mnt/trip/mapd/data
I1004 23:47:41.052510 12241 Calcite.cpp:95] Running calcite server as a daemon
E1004 23:47:41.370436 12241 Calcite.cpp:101] Appears to be orphaned Calcite serve already running, shutting it down
E1004 23:47:41.370517 12241 Calcite.cpp:102] Please check that you are not trying to run two servers on same port
E1004 23:47:41.370537 12241 Calcite.cpp:103] Attempting to shutdown orphaned Calcite server
E1004 23:47:41.381640 12241 Calcite.cpp:109] orphaned Calcite server shutdown
I1004 23:47:41.706120 12241 Calcite.cpp:124] Calcite server start took 300 ms
I1004 23:47:41.706172 12241 Calcite.cpp:125] ping took 22 ms
I1004 23:47:41.711787 12241 Calcite.cpp:281] [{"name":"Tan","ret":"double","args":["double"]},{"name":"Truncate__","ret":"float","args":["float","i32"]},{"name":"ln","ret":"double","args":["double"]},{"name":"distance_in_meters__","ret":"double","args":["float","float","float","float"]},{"name":"Floor__","ret":"float","args":["float"]},{"name":"Floor__2","ret":"i32","args":["i32"]},{"name":"Floor__3","ret":"i64","args":["i64"]},{"name":"Truncate","ret":"double","args":["double","i32"]},{"name":"Floor__1","ret":"i16","args":["i16"]},{"name":"radians","ret":"double","args":["double"]},{"name":"degrees","ret":"double","args":["double"]},{"name":"Ceil__","ret":"float","args":["float"]},{"name":"ln__","ret":"double","args":["float"]},{"name":"approx_distance_in_meters","ret":"double","args":["float","float","float","float"]},{"name":"Ceil__2","ret":"i32","args":["i32"]},{"name":"Ceil__1","ret":"i16","args":["i16"]},{"name":"Ceil__3","ret":"i64","args":["i64"]},{"name":"power","ret":"double","args":["double","double"]},{"name":"conv_4326_900913_x","ret":"double","args":["double"]},{"name":"conv_4326_900913_y","ret":"double","args":["double"]},{"name":"Atan","ret":"double","args":["double"]},{"name":"Floor","ret":"double","args":["double"]},{"name":"Log10","ret":"double","args":["double"]},{"name":"Truncate__1","ret":"i16","args":["i16","i32"]},{"name":"Truncate__2","ret":"i32","args":["i32","i32"]},{"name":"Log","ret":"double","args":["double"]},{"name":"Truncate__3","ret":"i64","args":["i64","i32"]},{"name":"Cos","ret":"double","args":["double"]},{"name":"Log__","ret":"double","args":["float"]},{"name":"Log10__","ret":"double","args":["float"]},{"name":"Asin","ret":"double","args":["double"]},{"name":"Cot","ret":"double","args":["double"]},{"name":"Tan__","ret":"double","args":["float"]},{"name":"distance_in_meters","ret":"double","args":["double","double","double","double"]},{"name":"round_to_digit","ret":"double","args":["double","i32"]},{"name":"Atan2","ret":"double","args":["double","double"]},{"name":"Acos","ret":"double","args":["double"]},{"name":"pi","ret":"double","args":[]},{"name":"Sin","ret":"double","args":["double"]},{"name":"Ceil","ret":"double","args":["double"]},{"name":"Exp","ret":"double","args":["double"]}]
E1004 23:47:41.712116 12241 MapDHandler.cpp:172] No GPUs detected, falling back to CPU mode
I1004 23:47:41.712280 12241 MapDHandler.cpp:181] Started in CPU mode
I1004 23:48:01.388016 12265 MapDHandler.cpp:311] User mapd connected to database mapd
I1004 23:48:01.432214 12265 MapDHandler.cpp:2090] select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);
I1004 23:48:01.434177 12265 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);'
I1004 23:48:17.079310 12264 FileMgr.cpp:116] Read table metadata, Epoch is 134799 for table data at '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1005 00:08:28.929255 12265 Calcite.cpp:260] Time in Thrift 45 (ms), Time in Java Calcite server 1227449 (ms)
I1005 00:08:29.026374 12265 RelAlgOptimizer.cpp:301] ID=5 (RelProject<140318729320304> (RexInput 1<PHONE_NUMBER>20032)) deleted!
I1005 00:08:29.026932 12265 RelAlgOptimizer.cpp:706] (RelProject<140318729253456> (RexInput 0<PHONE_NUMBER>54192) (RexInput 5<PHONE_NUMBER>54192)) eliminated 1 columns.
I1005 00:08:29.027029 12265 RelAlgOptimizer.cpp:706] (RelAggregate<140318729320032>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1005 00:08:29.503226 12399 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1005 00:09:20.632467 12265 MapDHandler.cpp:2188] Total: 1279200 (ms), Execution: 1279168 (ms)
I1005 00:09:20.666656 12265 MapDHandler.cpp:321] User mapd disconnected from database mapd
I1005 00:27:55.632702 12270 MapDHandler.cpp:311] User mapd connected to database mapd
I1005 00:27:55.633719 12270 MapDHandler.cpp:2090] select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);
I1005 00:27:55.634567 12270 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);'
I1005 00:27:55.677237 12270 Calcite.cpp:260] Time in Thrift 2 (ms), Time in Java Calcite server 40 (ms)
I1005 00:27:55.677875 12270 RelAlgOptimizer.cpp:301] ID=5 (RelProject<140313294003328> (RexInput 1<PHONE_NUMBER>03056)) deleted!
I1005 00:27:55.678076 12270 RelAlgOptimizer.cpp:706] (RelProject<140313293998464> (RexInput 0<PHONE_NUMBER>00288) (RexInput 5<PHONE_NUMBER>00288)) eliminated 1 columns.
I1005 00:27:55.678119 12270 RelAlgOptimizer.cpp:706] (RelAggregate<140313294003056>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1005 00:27:55.835714 12270 MapDHandler.cpp:2188] Total: 201 (ms), Execution: 200 (ms)
I1005 00:27:55.836180 12270 MapDHandler.cpp:321] User mapd disconnected from database mapd

It is taking over 1227 seconds to read the metadata of your single table
I1005 00:08:28.929255 12265 Calcite.cpp:260] Time in Thrift 45 (ms), Time in Java Calcite server 1227449 (ms)

Please bring your branch up to date and rerun the queries and we will get more info as there have been changes in that area to generate more detailed information, but it appears you have done a very large number of potentially small inserts into the table which will cause a lot of checkpoints to be written which need to be  read and processed when the DB first tries to access that table.

I just also found that any query immediately after mapd core starts took that long time too :)
Yeah. The table was not loaded by LOAD but by (many many) batches of INSERT which tried to simulate data injection in normal IoT applications. I was not aware that caused a lot of checkpoints to be written.

@dwayneberry
New code is 5 mins faster.
$ time echo "select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);" | /mnt/mapd-core/bin/mapdql mapd     -u $MAPD_USE
RNAME     -p $MAPD_PASSWORD
User mapd connected to database mapd
EXPR$0
1
User mapd disconnected from database mapd

real	14m57.288s
user	0m0.004s
sys	0m0.004s

Here is the INFO log:
$ tail -f /mnt/trip/mapd/data/mapd_log/mapd_server.INFO
I1005 03:18:28.604209  5632 Calcite.cpp:156] Creating Calcite Handler,  Calcite Port is 9093 base data dir is /mnt/trip/mapd/data
I1005 03:18:28.604238  5632 Calcite.cpp:95] Running calcite server as a daemon
I1005 03:18:29.269129  5632 Calcite.cpp:124] Calcite server start took 600 ms
I1005 03:18:29.269230  5632 Calcite.cpp:125] ping took 30 ms
I1005 03:18:29.275961  5632 Calcite.cpp:281] [{"name":"Tan","ret":"double","args":["double"]},{"name":"Truncate__","ret":"float","args":["float","i32"]},{"name":"ln","ret":"double","args":["double"]},{"name":"distance_in_meters__","ret":"double","args":["float","float","float","float"]},{"name":"Floor__","ret":"float","args":["float"]},{"name":"Floor__2","ret":"i32","args":["i32"]},{"name":"Floor__3","ret":"i64","args":["i64"]},{"name":"Truncate","ret":"double","args":["double","i32"]},{"name":"Floor__1","ret":"i16","args":["i16"]},{"name":"radians","ret":"double","args":["double"]},{"name":"degrees","ret":"double","args":["double"]},{"name":"Ceil__","ret":"float","args":["float"]},{"name":"ln__","ret":"double","args":["float"]},{"name":"approx_distance_in_meters","ret":"double","args":["float","float","float","float"]},{"name":"Ceil__2","ret":"i32","args":["i32"]},{"name":"Ceil__1","ret":"i16","args":["i16"]},{"name":"Ceil__3","ret":"i64","args":["i64"]},{"name":"power","ret":"double","args":["double","double"]},{"name":"conv_4326_900913_x","ret":"double","args":["double"]},{"name":"conv_4326_900913_y","ret":"double","args":["double"]},{"name":"Atan","ret":"double","args":["double"]},{"name":"Floor","ret":"double","args":["double"]},{"name":"Log10","ret":"double","args":["double"]},{"name":"Truncate__1","ret":"i16","args":["i16","i32"]},{"name":"Truncate__2","ret":"i32","args":["i32","i32"]},{"name":"Log","ret":"double","args":["double"]},{"name":"Truncate__3","ret":"i64","args":["i64","i32"]},{"name":"Cos","ret":"double","args":["double"]},{"name":"Log__","ret":"double","args":["float"]},{"name":"Log10__","ret":"double","args":["float"]},{"name":"Asin","ret":"double","args":["double"]},{"name":"Cot","ret":"double","args":["double"]},{"name":"Tan__","ret":"double","args":["float"]},{"name":"distance_in_meters","ret":"double","args":["double","double","double","double"]},{"name":"round_to_digit","ret":"double","args":["double","i32"]},{"name":"Atan2","ret":"double","args":["double","double"]},{"name":"Acos","ret":"double","args":["double"]},{"name":"pi","ret":"double","args":[]},{"name":"Sin","ret":"double","args":["double"]},{"name":"Ceil","ret":"double","args":["double"]},{"name":"Exp","ret":"double","args":["double"]}]
E1005 03:18:29.276314  5632 MapDHandler.cpp:174] No GPUs detected, falling back to CPU mode
I1005 03:18:29.276355  5632 MapDHandler.cpp:183] Started in CPU mode
I1005 03:18:32.843989  5659 MapDHandler.cpp:314] User mapd connected to database mapd
I1005 03:18:32.844525  5659 MapDHandler.cpp:2181] select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);
I1005 03:18:32.845162  5659 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);'
I1005 03:22:41.262905  5654 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 247482ms Epoch: 134799 files read: 544 table location: '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1005 03:32:37.907827  5654 Catalog.cpp:1510] Instantiating Fragmenter for table trips took 844152ms
I1005 03:32:38.021816  5654 Catalog.cpp:1556] Time to load Dictionary 1 was 112ms
I1005 03:32:38.096951  5654 Catalog.cpp:1556] Time to load Dictionary 2 was 75ms
I1005 03:32:38.170095  5654 Catalog.cpp:1556] Time to load Dictionary 3 was 73ms
I1005 03:32:38.226166  5654 Catalog.cpp:1556] Time to load Dictionary 4 was 56ms
I1005 03:32:38.652088  5659 Calcite.cpp:260] Time in Thrift 7 (ms), Time in Java Calcite server 845799 (ms)
I1005 03:32:38.684180  5659 RelAlgOptimizer.cpp:301] ID=5 (RelProject<139645895849840> (RexInput 1<PHONE_NUMBER>49568)) deleted!
I1005 03:32:38.684833  5659 RelAlgOptimizer.cpp:707] (RelProject<139645895782992> (RexInput 0<PHONE_NUMBER>83728) (RexInput 5<PHONE_NUMBER>83728)) eliminated 1 columns.
I1005 03:32:38.684877  5659 RelAlgOptimizer.cpp:707] (RelAggregate<139645895849568>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1005 03:32:39.012008  8480 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1005 03:33:30.045377  5659 MapDHandler.cpp:2279] Total: 897200 (ms), Execution: 897160 (ms)
I1005 03:33:30.109776  5659 MapDHandler.cpp:324] User mapd disconnected from database mapd

Bought 8GB RAM today. That significantly improves performance of the query after mapd cold starts.
$ time echo "select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);" | /mnt/mapd-core/bin/mapdql mapd
 -u $MAPD_USERNAME     -p $MAPD_PASSWORD
User mapd connected to database mapd
EXPR$0
1
User mapd disconnected from database mapd

real	5m2.900s
user	0m0.008s
sys	0m0.016s

Interestingly, with extra 8GB RAM, the other database (CH) uses 150 secs to complete the same query on cold start, but it still uses 150s on 2nd+ queries. In contrast, MapD uses <1s on 2nd+ queries 👍  I guess, MapD's TEXT ENCODING DICT data type plays a critical role here. CH has no similar data type so it has to load 0.5B string column values every time which can't fit in my 14GB total memory. Such a guess can be foiled by a different query that needs a smaller-size column than medallion. For example, to complete the following query on cold start:
select count(*) from (select max(pickup_datetime) from trips prewhere dropoff_datetime = '2014-04-23 03:17:00' group by dropoff_datetime)
MapD uses 5m55s; CH uses 22s. After warm up, both databases took almost the same time (<1s) to finish 2nd+ instances of the query.
This issue seems resolvable or alleviated simply by adding more memory, so i think this issue can be closed.

Hi @dwayneberry. Found a way to speed up "cold start" of  BIG tables.
From profiling, bottleneck is the for-loop of FileInfo::openExistingFile. Key factor seems more on the number of pages of a table than on the number of checkpoints.
The idea behind is simple -- gather 'headers' of all pages in a file and relocate them to front of the file to form a 'super page'. This way, it take only few milliseconds to read the super page of a file which contains all headers of the file.
In contrast, previously for each file it took 3-15 seconds to load the headers thru many fseek/fread operations.
From INFO log below, with this file format, loading table schema of a 0.5B-row table takes <2s and execution of the first query on cold start now took 53s to finish. (versus previous 247s on loading schema and 360s on query)
E1009 09:03:33.604703 30227 MapDHandler.cpp:174] No GPUs detected, falling back to CPU mode
I1009 09:03:33.604737 30227 MapDHandler.cpp:183] Started in CPU mode
I1009 09:04:06.482470 30304 MapDHandler.cpp:314] User mapd connected to database mapd
I1009 09:04:06.520790 30304 MapDHandler.cpp:2181] select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);
I1009 09:04:06.525681 30304 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);'
I1009 09:04:09.405311 30302 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 1984ms Epoch: 3920 files read: 94 table location: '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1009 09:04:19.192484 30302 Catalog.cpp:1510] Instantiating Fragmenter for table trips took 11782ms
I1009 09:04:19.332147 30302 Catalog.cpp:1556] Time to load Dictionary 1 was 139ms
I1009 09:04:19.409219 30302 Catalog.cpp:1556] Time to load Dictionary 2 was 76ms
I1009 09:04:19.495249 30302 Catalog.cpp:1556] Time to load Dictionary 3 was 85ms
I1009 09:04:19.546556 30302 Catalog.cpp:1556] Time to load Dictionary 4 was 51ms
I1009 09:04:19.837051 30304 Calcite.cpp:260] Time in Thrift 20 (ms), Time in Java Calcite server 13291 (ms)
I1009 09:04:19.852845 30304 RelAlgOptimizer.cpp:301] ID=5 (RelProject<139695489300336> (RexInput 1<PHONE_NUMBER>00064)) deleted!
I1009 09:04:19.853183 30304 RelAlgOptimizer.cpp:707] (RelProject<139695489233488> (RexInput 0<PHONE_NUMBER>34224) (RexInput 5<PHONE_NUMBER>34224)) eliminated 1 columns.
I1009 09:04:19.853225 30304 RelAlgOptimizer.cpp:707] (RelAggregate<139695489300064>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1009 09:04:20.286516 32514 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1009 09:04:59.818516 30304 MapDHandler.cpp:2279] Total: 53297 (ms), Execution: 53297 (ms)

This time i used LOAD to load the 0.5B rows. The number of checkpoints are only 1/5 (i don't know why:) of previous case that loaded the table by bulk INSERT's. However, comparing the schema load time (1.9s vs 247s), the 5 times less checkpoint number seems not a major factor. I feel, elimination of numerous fseeks/freads from the for loop is.
Of course, though this new file format can save much time on cold starting real BIG tables, it has no backward compatibility, so it's only for reference.

Before this experimental file format, i also tried parallelizing the for-loop. It didn't improve at all. More threads (multiplied by the thread count initiated by FileMgr::init) competing for disk i/o made the situation even worse; system load constantly shoot to 30+ without throughput gain.
Due to no backward compatibility (unless code tuned to accept dual formats) and any side effect yet to know, a PR for this change seems improper for now. A diff of code is here for review only if interested:
$ git diff
diff --git a/CMakeLists.txt b/CMakeLists.txt
old mode 100644
new mode 100755
index 4bf5e93..9dddb54
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -239,7 +239,7 @@ add_library(mapd_thrift
     ${CMAKE_BINARY_DIR}/gen-cpp/MapD.h
     ${CMAKE_BINARY_DIR}/gen-cpp/mapd_constants.cpp
     ${CMAKE_BINARY_DIR}/gen-cpp/mapd_types.cpp)
-target_link_libraries(mapd_thrift ${Thrift_LIBRARIES})
+target_link_libraries(mapd_thrift ${Thrift_LIBRARIES} tbb)

 option(ENABLE_JOIN_EXEC "Enable RA vm to execute join node" ON)
 if(ENABLE_JOIN_EXEC)
@@ -369,11 +369,11 @@ add_custom_target(rerun_cmake ALL
   )
 add_dependencies(mapd_server rerun_cmake)

-target_link_libraries(mapd_server mapd_thrift thrift_handler ${MAPD_LIBRARIES} ${Boost_LIBRARIES} ${Glog_LIBRARIES} ${CMAKE_DL_LIBS} ${CUDA_LIBRARIES} ${LLVM_LINKER_FLAGS} ${PROFILER_LIBS} ${CURSES_LIBRARIES} ${ZLIB_LIBRARIES} poly2tri)
+target_link_libraries(mapd_server mapd_thrift thrift_handler ${MAPD_LIBRARIES} ${Boost_LIBRARIES} ${Glog_LIBRARIES} ${CMAKE_DL_LIBS} ${CUDA_LIBRARIES} ${LLVM_LINKER_FLAGS} ${PROFILER_LIBS} ${CURSES_LIBRARIES} ${ZLIB_LIBRARIES} poly2tri tbb)
 if(ENABLE_FOLLY)
-target_link_libraries(initdb Shared Catalog Fragmenter Chunk SqliteConnector DataMgr StringDictionary ${Boost_LIBRARIES} ${Folly_LIBRARIES} ${CMAKE_DL_LIBS})
+target_link_libraries(initdb Shared Catalog Fragmenter Chunk SqliteConnector DataMgr StringDictionary ${Boost_LIBRARIES} ${Folly_LIBRARIES} ${CMAKE_DL_LIBS} tbb)
 else()
-target_link_libraries(initdb Shared Catalog Fragmenter Chunk SqliteConnector DataMgr StringDictionary ${Boost_LIBRARIES} ${CMAKE_DL_LIBS})
+target_link_libraries(initdb Shared Catalog Fragmenter Chunk SqliteConnector DataMgr StringDictionary ${Boost_LIBRARIES} ${CMAKE_DL_LIBS} tbb)
 endif()

 macro(set_dpkg_arch arch_in arch_out)
diff --git a/DataMgr/FileMgr/File.cpp b/DataMgr/FileMgr/File.cpp
old mode 100644
new mode 100755
index bdfc009..147cff6
--- a/DataMgr/FileMgr/File.cpp
+++ b/DataMgr/FileMgr/File.cpp
@@ -42,12 +42,12 @@ FILE* create(const std::string& basePath, const int fileId, const size_t pageSiz
   if (f == nullptr) {
     LOG(FATAL) << "Error trying to create file '" << path << "', the errno is " << errno;
   }
-  fseek(f, (pageSize * numPages) - 1, SEEK_SET);
+  fseek(f, SUPER_PAGE_SIZE + (pageSize * numPages) - 1, SEEK_SET);
   fputc(EOF, f);
   fseek(f, 0, SEEK_SET);  // rewind
-  if (fileSize(f) != pageSize * numPages) {
+  if (fileSize(f) != SUPER_PAGE_SIZE + pageSize * numPages) {
     LOG(FATAL) << "Error trying to create file '" << path << "', file size " << fileSize(f)
-               << " does not equal pageSize * numPages " << pageSize * numPages;
+               << " does not equal pageSize * numPages " << SUPER_PAGE_SIZE + pageSize * numPages;
   }

   return f;
@@ -62,12 +62,12 @@ FILE* create(const std::string& fullPath, const size_t requestedFileSize) {
   if (f == nullptr) {
     LOG(FATAL) << "Error trying to create file '" << fullPath << "', the errno is " << errno;
   }
-  fseek(f, requestedFileSize - 1, SEEK_SET);
+  fseek(f, SUPER_PAGE_SIZE + requestedFileSize - 1, SEEK_SET);
   fputc(EOF, f);
   fseek(f, 0, SEEK_SET);  // rewind
-  if (fileSize(f) != requestedFileSize) {
+  if (fileSize(f) != SUPER_PAGE_SIZE + requestedFileSize) {
     LOG(FATAL) << "Error trying to create file '" << fullPath << "', file size " << fileSize(f)
-               << " does not equal requestedFileSize " << requestedFileSize;
+               << " does not equal requestedFileSize " << SUPER_PAGE_SIZE + requestedFileSize;
   }
   return f;
 }
@@ -122,7 +122,7 @@ size_t append(FILE* f, const size_t size, int8_t* buf) {
 }

 size_t readPage(FILE* f, const size_t pageSize, const size_t pageNum, int8_t* buf) {
-  return read(f, pageNum * pageSize, pageSize, buf);
+  return read(f, SUPER_PAGE_SIZE + pageNum * pageSize, pageSize, buf);
 }

 size_t readPartialPage(FILE* f,
@@ -131,11 +131,11 @@ size_t readPartialPage(FILE* f,
                        const size_t readSize,
                        const size_t pageNum,
                        int8_t* buf) {
-  return read(f, pageNum * pageSize + offset, readSize, buf);
+  return read(f, SUPER_PAGE_SIZE + pageNum * pageSize + offset, readSize, buf);
 }

 size_t writePage(FILE* f, const size_t pageSize, const size_t pageNum, int8_t* buf) {
-  return write(f, pageNum * pageSize, pageSize, buf);
+  return write(f, SUPER_PAGE_SIZE + pageNum * pageSize, pageSize, buf);
 }

 size_t writePartialPage(FILE* f,
@@ -144,7 +144,7 @@ size_t writePartialPage(FILE* f,
                         const size_t writeSize,
                         const size_t pageNum,
                         int8_t* buf) {
-  return write(f, pageNum * pageSize + offset, writeSize, buf);
+  return write(f, SUPER_PAGE_SIZE + pageNum * pageSize + offset, writeSize, buf);
 }

 size_t appendPage(FILE* f, const size_t pageSize, int8_t* buf) {
diff --git a/DataMgr/FileMgr/File.h b/DataMgr/FileMgr/File.h
old mode 100644
new mode 100755
index 3943f4e..b41d262
--- a/DataMgr/FileMgr/File.h
+++ b/DataMgr/FileMgr/File.h
@@ -33,6 +33,15 @@

 namespace File_Namespace {

+//ppan# moved from FileBuffer.cpp
+#define METADATA_PAGE_SIZE 4096
+
+//ppan+ this super page resides at front of a file and must
+//be big enough to hold 'headers' of maximum number of 'pages'.
+#define SUPER_PAGE_SIZE (1 << 18)
+#define SUPER_HEAD_SIZE (SUPER_PAGE_SIZE / METADATA_PAGE_SIZE)
+
+
 FILE* create(const std::string& basePath, const int fileId, const size_t pageSize, const size_t npages);

 FILE* create(const std::string& fullPath, const size_t requestedFileSize);
diff --git a/DataMgr/FileMgr/FileBuffer.cpp b/DataMgr/FileMgr/FileBuffer.cpp
old mode 100644
new mode 100755
index 6b45434..4d64584
--- a/DataMgr/FileMgr/FileBuffer.cpp
+++ b/DataMgr/FileMgr/FileBuffer.cpp
@@ -28,8 +28,6 @@
 #include <thread>
 #include <future>

-#define METADATA_PAGE_SIZE 4096
-
 using namespace std;

 namespace File_Namespace {
@@ -151,6 +149,10 @@ void FileBuffer::calcHeaderBuffer() {
   if (headerMod > 0) {
     reservedHeaderSize_ += headerBufferOffset_ - headerMod;
   }
+
+  //ppan+ no need this in new format !!!
+  reservedHeaderSize_ = 0;
+
   // pageDataSize_ = pageSize_-reservedHeaderSize_;
 }

@@ -356,12 +358,12 @@ void FileBuffer::writeHeader(Page& page, const int pageId, const int epoch, cons
   header[intHeaderSize - 1] = epoch;
   FileInfo* fileInfo = fm_->getFileInfoForFileId(page.fileId);
   size_t pageSize = writeMetadata ? METADATA_PAGE_SIZE : pageSize_;
-  fileInfo->write(page.pageNum * pageSize, (intHeaderSize) * sizeof(int), (int8_t*)&header[0]);
+  fileInfo->write(page.pageNum * SUPER_HEAD_SIZE - SUPER_PAGE_SIZE, (intHeaderSize) * sizeof(int), (int8_t*)&header[0]);
 }

 void FileBuffer::readMetadata(const Page& page) {
   FILE* f = fm_->getFileForFileId(page.fileId);
-  fseek(f, page.pageNum * METADATA_PAGE_SIZE + reservedHeaderSize_, SEEK_SET);
+  fseek(f, SUPER_PAGE_SIZE + page.pageNum * METADATA_PAGE_SIZE + reservedHeaderSize_, SEEK_SET);
   fread((int8_t*)&pageSize_, sizeof(size_t), 1, f);
   fread((int8_t*)&size_, sizeof(size_t), 1, f);
   vector<int> typeData(
@@ -390,7 +392,7 @@ void FileBuffer::writeMetadata(const int epoch) {
   Page page = fm_->requestFreePage(METADATA_PAGE_SIZE, true);
   writeHeader(page, -1, epoch, true);
   FILE* f = fm_->getFileForFileId(page.fileId);
-  fseek(f, page.pageNum * METADATA_PAGE_SIZE + reservedHeaderSize_, SEEK_SET);
+  fseek(f, SUPER_PAGE_SIZE + page.pageNum * METADATA_PAGE_SIZE + reservedHeaderSize_, SEEK_SET);
   fwrite((int8_t*)&pageSize_, sizeof(size_t), 1, f);
   fwrite((int8_t*)&size_, sizeof(size_t), 1, f);
   vector<int> typeData(
diff --git a/DataMgr/FileMgr/FileInfo.cpp b/DataMgr/FileMgr/FileInfo.cpp
old mode 100644
new mode 100755
index a7ec847..83cc2ce
--- a/DataMgr/FileMgr/FileInfo.cpp
+++ b/DataMgr/FileMgr/FileInfo.cpp
@@ -19,6 +19,7 @@
 #include "Page.h"
 #include <glog/logging.h>
 #include <iostream>
+#include <memory>

 #include <utility>
 using namespace std;
@@ -45,19 +46,19 @@ void FileInfo::initNewFile() {
   int headerSize = 0;
   int8_t* headerSizePtr = (int8_t*)(&headerSize);
   for (size_t pageId = 0; pageId < numPages; ++pageId) {
-    File_Namespace::write(f, pageId * pageSize, sizeof(int), headerSizePtr);
+    File_Namespace::write(f, pageId * SUPER_HEAD_SIZE, sizeof(int), headerSizePtr);
     freePages.insert(pageId);
   }
 }

 size_t FileInfo::write(const size_t offset, const size_t size, int8_t* buf) {
   std::lock_guard<std::mutex> lock(readWriteMutex_);
-  return File_Namespace::write(f, offset, size, buf);
+  return File_Namespace::write(f, SUPER_PAGE_SIZE + offset, size, buf);
 }

 size_t FileInfo::read(const size_t offset, const size_t size, int8_t* buf) {
   std::lock_guard<std::mutex> lock(readWriteMutex_);
-  return File_Namespace::read(f, offset, size, buf);
+  return File_Namespace::read(f, SUPER_PAGE_SIZE + offset, size, buf);
 }

 void FileInfo::openExistingFile(std::vector<HeaderInfo>& headerVec, const int fileMgrEpoch) {
@@ -66,11 +67,15 @@ void FileInfo::openExistingFile(std::vector<HeaderInfo>& headerVec, const int fi
   int oldPageId = -99;
   int oldVersionEpoch = -99;
   int skipped = 0;
+
+  //ppan+ read the whole super page to memory
+  std::unique_ptr<int8_t> spage(new int8_t[SUPER_PAGE_SIZE]);
+  size_t nread = pread(fileno(f), spage.get(), SUPER_PAGE_SIZE, 0);
+
   for (size_t pageNum = 0; pageNum < numPages; ++pageNum) {
-    int headerSize;
-    fseek(f, pageNum * pageSize, SEEK_SET);
-    fread((int8_t*)(&headerSize), sizeof(int), 1, f);
-    if (headerSize != 0) {
+    int* ip = (int*)(spage.get() + pageNum * SUPER_HEAD_SIZE);
+    int headerSize = *ip++;
+    if (headerSize != 0 && pageNum < nread / SUPER_HEAD_SIZE) {
       // headerSize doesn't include headerSize itself
       // We're tying ourself to headers of ints here
       size_t numHeaderElems = headerSize / sizeof(int);
@@ -83,11 +88,12 @@ void FileInfo::openExistingFile(std::vector<HeaderInfo>& headerVec, const int fi
       // size_t chunkSize;
       // We don't want to read headerSize in our header - so start
       // reading 4 bytes past it
-      fread((int8_t*)(&chunkKey[0]), headerSize - 2 * sizeof(int), 1, f);
+      for (int i = 0; i < (int)((headerSize - 2 * sizeof(int)) / sizeof(int)); ++i)
+          chunkKey[i] = *ip++;
       // cout << "Chunk key: " << showChunk(chunkKey) << endl;
-      fread((int8_t*)(&pageId), sizeof(int), 1, f);
+      pageId = *ip++;
       // cout << "Page id: " << pageId << endl;
-      fread((int8_t*)(&versionEpoch), sizeof(int), 1, f);
+      versionEpoch = *ip++;
       if (chunkKey != oldChunkKey || oldPageId != pageId - (1 + skipped)) {
         if (skipped > 0) {
           VLOG(1) << "\tChunk key: " << showChunk(oldChunkKey) << " Page id from : " << oldPageId
@@ -118,7 +124,7 @@ void FileInfo::openExistingFile(std::vector<HeaderInfo>& headerVec, const int fi
         // First write 0 to first four bytes of
         // header to mark as free
         headerSize = 0;
-        File_Namespace::write(f, pageNum * pageSize, sizeof(int), (int8_t*)&headerSize);
+        File_Namespace::write(f, pageNum * SUPER_HEAD_SIZE, sizeof(int), (int8_t*)&headerSize);
         // Now add page to free list
         freePages.insert(pageNum);
         LOG(WARNING) << "Was not checkpointed: Chunk key: " << showChunk(chunkKey) << " Page id: " << pageId
@@ -148,7 +154,7 @@ void FileInfo::openExistingFile(std::vector<HeaderInfo>& headerVec, const int fi
 void FileInfo::freePage(int pageId) {
   int zeroVal = 0;
   int8_t* zeroAddr = reinterpret_cast<int8_t*>(&zeroVal);
-  File_Namespace::write(f, pageId * pageSize, sizeof(int), zeroAddr);
+  File_Namespace::write(f, pageId * SUPER_HEAD_SIZE, sizeof(int), zeroAddr);
   std::lock_guard<std::mutex> lock(freePagesMutex_);
   freePages.insert(pageId);
 }
diff --git a/DataMgr/FileMgr/FileInfo.h b/DataMgr/FileMgr/FileInfo.h
old mode 100644
new mode 100755
diff --git a/DataMgr/FileMgr/FileMgr.cpp b/DataMgr/FileMgr/FileMgr.cpp
old mode 100644
new mode 100755
index 0de7622..0da768c
--- a/DataMgr/FileMgr/FileMgr.cpp
+++ b/DataMgr/FileMgr/FileMgr.cpp
@@ -147,8 +147,8 @@ void FileMgr::init(const size_t num_reader_threads) {
           size_t pageSize = boost::lexical_cast<size_t>(fileStem.substr(dotPos + 1, fileStem.size()));
           std::string filePath(fileIt->path().string());
           size_t fileSize = boost::filesystem::file_size(filePath);
-          assert(fileSize % pageSize == 0);  // should be no partial pages
-          size_t numPages = fileSize / pageSize;
+          assert((fileSize - SUPER_PAGE_SIZE) % pageSize == 0);  // should be no partial pages
+          size_t numPages = (fileSize - SUPER_PAGE_SIZE) / pageSize;

           VLOG(1) << "File id: " << fileId << " Page size: " << pageSize << " Num pages: " << numPages;

@@ -301,8 +301,8 @@ void FileMgr::init(const std::string dataPathToConvertFrom) {
           size_t pageSize = boost::lexical_cast<size_t>(fileStem.substr(dotPos + 1, fileStem.size()));
           std::string filePath(fileIt->path().string());
           size_t fileSize = boost::filesystem::file_size(filePath);
-          assert(fileSize % pageSize == 0);  // should be no partial pages
-          size_t numPages = fileSize / pageSize;
+          assert((fileSize - SUPER_PAGE_SIZE) % pageSize == 0);  // should be no partial pages
+          size_t numPages = (fileSize - SUPER_PAGE_SIZE) / pageSize;

           file_futures.emplace_back(std::async(std::launch::async, [filePath, fileId, pageSize, numPages, this] {
             std::vector<HeaderInfo> tempHeaderVec;

Forgot to rerun the query that needs a smaller column. Quoted:
Such a guess can be foiled by a different query that needs a smaller-size column than medallion column. For example, to complete the following query on cold start:

    select count(*) from (select max(pickup_datetime) from trips prewhere dropoff_datetime = '2014-04-23
    03:17:00' group by dropoff_datetime)

MapD uses 5m55s; CH uses 22s. After warm up, both databases took almost the same time (<1s) to finish 2nd+ instances of the query.

For that query, with new file format, after cold start (all file cache was cleared) the time used are very close now (26s vs 22s):
$ time echo "select count(*) from (select max(pickup_datetime) from trips where dropoff_datetime = '2014-04-23 03:17:00' group by dropoff_datetime);" | /mnt/mapd-core/bin/mapdql mapd     -u $MAPD_US
ERNAME     -p $MAPD_PASSWORD
User mapd connected to database mapd
EXPR$0
1
User mapd disconnected from database mapd

real	0m26.083s
user	0m0.004s
sys	0m0.004s

$ tail -f /mnt/trip/mapd/data/mapd_log/mapd_server.INFO
E1009 16:54:06.409965  5376 MapDHandler.cpp:142] This build isn't CUDA enabled, will run on CPU
I1009 16:54:06.411263  5376 DataMgr.cpp:120] cpuSlabSize is 4096M
I1009 16:54:06.427644  5376 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 0ms Epoch: 0 files read: 0 table location: '/mnt/trip/mapd/data/mapd_data/table_0_0/'
I1009 16:54:06.430061  5376 Calcite.cpp:156] Creating Calcite Handler,  Calcite Port is 9093 base data dir is /mnt/trip/mapd/data
I1009 16:54:06.430079  5376 Calcite.cpp:95] Running calcite server as a daemon
I1009 16:54:07.088037  5376 Calcite.cpp:124] Calcite server start took 600 ms
I1009 16:54:07.088114  5376 Calcite.cpp:125] ping took 29 ms
I1009 16:54:07.100267  5376 Calcite.cpp:281] [{"name":"Tan","ret":"double","args":["double"]},{"name":"Truncate__","ret":"float","args":["float","i32"]},{"name":"ln","ret":"double","args":["double"]},{"name":"distance_in_meters__","ret":"double","args":["float","float","float","float"]},{"name":"Floor__","ret":"float","args":["float"]},{"name":"Floor__2","ret":"i32","args":["i32"]},{"name":"Floor__3","ret":"i64","args":["i64"]},{"name":"Truncate","ret":"double","args":["double","i32"]},{"name":"Floor__1","ret":"i16","args":["i16"]},{"name":"radians","ret":"double","args":["double"]},{"name":"degrees","ret":"double","args":["double"]},{"name":"Ceil__","ret":"float","args":["float"]},{"name":"ln__","ret":"double","args":["float"]},{"name":"approx_distance_in_meters","ret":"double","args":["float","float","float","float"]},{"name":"Ceil__2","ret":"i32","args":["i32"]},{"name":"Ceil__1","ret":"i16","args":["i16"]},{"name":"Ceil__3","ret":"i64","args":["i64"]},{"name":"power","ret":"double","args":["double","double"]},{"name":"conv_4326_900913_x","ret":"double","args":["double"]},{"name":"conv_4326_900913_y","ret":"double","args":["double"]},{"name":"Atan","ret":"double","args":["double"]},{"name":"Floor","ret":"double","args":["double"]},{"name":"Log10","ret":"double","args":["double"]},{"name":"Truncate__1","ret":"i16","args":["i16","i32"]},{"name":"Truncate__2","ret":"i32","args":["i32","i32"]},{"name":"Log","ret":"double","args":["double"]},{"name":"Truncate__3","ret":"i64","args":["i64","i32"]},{"name":"Cos","ret":"double","args":["double"]},{"name":"Log__","ret":"double","args":["float"]},{"name":"Log10__","ret":"double","args":["float"]},{"name":"Asin","ret":"double","args":["double"]},{"name":"Cot","ret":"double","args":["double"]},{"name":"Tan__","ret":"double","args":["float"]},{"name":"distance_in_meters","ret":"double","args":["double","double","double","double"]},{"name":"round_to_digit","ret":"double","args":["double","i32"]},{"name":"Atan2","ret":"double","args":["double","double"]},{"name":"Acos","ret":"double","args":["double"]},{"name":"pi","ret":"double","args":[]},{"name":"Sin","ret":"double","args":["double"]},{"name":"Ceil","ret":"double","args":["double"]},{"name":"Exp","ret":"double","args":["double"]}]
E1009 16:54:07.105474  5376 MapDHandler.cpp:174] No GPUs detected, falling back to CPU mode
I1009 16:54:07.105518  5376 MapDHandler.cpp:183] Started in CPU mode
I1009 16:55:14.112300  5397 MapDHandler.cpp:314] User mapd connected to database mapd
I1009 16:55:14.149191  5397 MapDHandler.cpp:2181] select count(*) from (select max(pickup_datetime) from trips where dropoff_datetime = '2014-04-23 03:17:00' group by dropoff_datetime);
I1009 16:55:14.154332  5397 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where dropoff_datetime = '2014-04-23 03:17:00' group by dropoff_datetime);'
I1009 16:55:17.068141  5399 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 1943ms Epoch: 3920 files read: 94 table location: '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1009 16:55:26.862198  5399 Catalog.cpp:1510] Instantiating Fragmenter for table trips took 11778ms
I1009 16:55:26.993620  5399 Catalog.cpp:1556] Time to load Dictionary 1 was 131ms
I1009 16:55:27.062726  5399 Catalog.cpp:1556] Time to load Dictionary 2 was 69ms
I1009 16:55:27.149145  5399 Catalog.cpp:1556] Time to load Dictionary 3 was 86ms
I1009 16:55:27.211570  5399 Catalog.cpp:1556] Time to load Dictionary 4 was 62ms
I1009 16:55:27.508219  5397 Calcite.cpp:260] Time in Thrift 17 (ms), Time in Java Calcite server 13336 (ms)
I1009 16:55:27.525780  5397 RelAlgOptimizer.cpp:301] ID=5 (RelProject<140323225614192> (RexInput 1<PHONE_NUMBER>13888)) deleted!
I1009 16:55:27.526129  5397 RelAlgOptimizer.cpp:707] (RelProject<140323225547296> (RexInput 6<PHONE_NUMBER>48000) (RexInput 5<PHONE_NUMBER>48000)) eliminated 1 columns.
I1009 16:55:27.526198  5397 RelAlgOptimizer.cpp:707] (RelAggregate<140323225613888>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1009 16:55:27.984529  7663 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1009 16:55:39.693989  5397 MapDHandler.cpp:2279] Total: 25544 (ms), Execution: 25543 (ms)
I1009 16:55:39.694561  5397 MapDHandler.cpp:324] User mapd disconnected from database mapd

FYI, Michael's off today for Canadian holiday.

Hi @fleapapa, would you mind making a PR for this so we can try it out more easily?

Hi @tmostak, no problem on the PR, but to not have different code changes mixed in one PR, i will need to stash the changes for this issue and make a PR for issue #105 first.
By the way,  due to #105, the data files currently in my database were created all through COPY statements, so there are not many checkpoints for double checking this issue. Once done with #105, i will re-load the database using bulk INSERT, which will create x5 checkpoints for double checking the issue. INSERT is relatively slower. It may be hours to pump 0.5B rows into the db. Will make the PR for this issue a little later.

Finally had 0.5B rows be INSERT-ed to the table. Number of checkpoints created is 507, similar to the number that @dwayneberry saw last time. This time, immediately after cold start and file cache was cleared, mapd core took 13s to load the table schema and took 5m47s to finish the same query.
E1011 23:00:33.947511   568 MapDHandler.cpp:142] This build isn't CUDA enabled, will run on CPU
I1011 23:00:33.947810   568 DataMgr.cpp:120] cpuSlabSize is 4096M
I1011 23:00:33.983031   568 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 15ms Epoch: 0 files read: 0 table location: '/mnt/trip/mapd/data/mapd_data/table_0_0/'
I1011 23:00:34.003734   568 Calcite.cpp:156] Creating Calcite Handler,  Calcite Port is 9093 base data dir is /mnt/trip/mapd/data
I1011 23:00:34.003762   568 Calcite.cpp:95] Running calcite server as a daemon
I1011 23:00:34.860302   568 Calcite.cpp:124] Calcite server start took 800 ms
I1011 23:00:34.860373   568 Calcite.cpp:125] ping took 29 ms
I1011 23:00:34.866739   568 Calcite.cpp:281] [{"name":"Tan","ret":"double","args":["double"]},{"name":"Truncate__","ret":"float","args":["float","i32"]},{"name":"ln","ret":"double","args":["double"]},{"name":"distance_in_meters__","ret":"double","args":["float","float","float","float"]},{"name":"Floor__","ret":"float","args":["float"]},{"name":"Floor__2","ret":"i32","args":["i32"]},{"name":"Floor__3","ret":"i64","args":["i64"]},{"name":"Truncate","ret":"double","args":["double","i32"]},{"name":"Floor__1","ret":"i16","args":["i16"]},{"name":"radians","ret":"double","args":["double"]},{"name":"degrees","ret":"double","args":["double"]},{"name":"Ceil__","ret":"float","args":["float"]},{"name":"ln__","ret":"double","args":["float"]},{"name":"approx_distance_in_meters","ret":"double","args":["float","float","float","float"]},{"name":"Ceil__2","ret":"i32","args":["i32"]},{"name":"Ceil__1","ret":"i16","args":["i16"]},{"name":"Ceil__3","ret":"i64","args":["i64"]},{"name":"power","ret":"double","args":["double","double"]},{"name":"conv_4326_900913_x","ret":"double","args":["double"]},{"name":"conv_4326_900913_y","ret":"double","args":["double"]},{"name":"Atan","ret":"double","args":["double"]},{"name":"Floor","ret":"double","args":["double"]},{"name":"Log10","ret":"double","args":["double"]},{"name":"Truncate__1","ret":"i16","args":["i16","i32"]},{"name":"Truncate__2","ret":"i32","args":["i32","i32"]},{"name":"Log","ret":"double","args":["double"]},{"name":"Truncate__3","ret":"i64","args":["i64","i32"]},{"name":"Cos","ret":"double","args":["double"]},{"name":"Log__","ret":"double","args":["float"]},{"name":"Log10__","ret":"double","args":["float"]},{"name":"Asin","ret":"double","args":["double"]},{"name":"Cot","ret":"double","args":["double"]},{"name":"Tan__","ret":"double","args":["float"]},{"name":"distance_in_meters","ret":"double","args":["double","double","double","double"]},{"name":"round_to_digit","ret":"double","args":["double","i32"]},{"name":"Atan2","ret":"double","args":["double","double"]},{"name":"Acos","ret":"double","args":["double"]},{"name":"pi","ret":"double","args":[]},{"name":"Sin","ret":"double","args":["double"]},{"name":"Ceil","ret":"double","args":["double"]},{"name":"Exp","ret":"double","args":["double"]}]
E1011 23:00:34.867075   568 MapDHandler.cpp:174] No GPUs detected, falling back to CPU mode
I1011 23:00:34.867102   568 MapDHandler.cpp:183] Started in CPU mode
I1011 23:01:25.598544   589 MapDHandler.cpp:314] User mapd connected to database mapd
I1011 23:01:25.644287   589 MapDHandler.cpp:2181] select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);
I1011 23:01:25.645490   589 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);'
I1011 23:01:39.569141   591 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 13031ms Epoch: 125156 files read: 505 table location: '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1011 23:06:35.585868   591 Catalog.cpp:1510] Instantiating Fragmenter for table trips took 309048ms
I1011 23:06:35.702114   591 Catalog.cpp:1556] Time to load Dictionary 1 was 116ms
I1011 23:06:35.838363   591 Catalog.cpp:1556] Time to load Dictionary 2 was 136ms
I1011 23:06:35.959408   591 Catalog.cpp:1556] Time to load Dictionary 3 was 120ms
I1011 23:06:36.064339   591 Catalog.cpp:1556] Time to load Dictionary 4 was 104ms
I1011 23:06:36.438885   589 Calcite.cpp:260] Time in Thrift 13 (ms), Time in Java Calcite server 310780 (ms)
I1011 23:06:36.439460   589 RelAlgOptimizer.cpp:301] ID=5 (RelProject<140736683325296> (RexInput 1<PHONE_NUMBER>25024)) deleted!
I1011 23:06:36.439644   589 RelAlgOptimizer.cpp:707] (RelProject<140736683258448> (RexInput 0<PHONE_NUMBER>59184) (RexInput 5<PHONE_NUMBER>59184)) eliminated 1 columns.
I1011 23:06:36.439684   589 RelAlgOptimizer.cpp:707] (RelAggregate<140736683325024>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1011 23:06:36.517798  3481 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1011 23:07:12.918454   589 MapDHandler.cpp:2279] Total: 347273 (ms), Execution: 347273 (ms)
I1011 23:07:12.918908   589 MapDHandler.cpp:324] User mapd disconnected from database mapd

It seems @dwayneberry is correct and i am wrong. Huh,,, the number of checkpoints is the major factor of the slowness???
Let me restore to old file format and double check it again. Sorry, this needs another 10+ hours to INSERT the 0.5B row in old format...

While i'm re-injecting 512M rows in old file format, from number of created files and table row count it is observed that average one checkpoint is created for every 1M rows.
173

User mapd connected to database mapd
EXPR$0
173179759

If a larger number of checkpoints (INSERT vs COPY) is the root cause of slowness, does it make sense to reduce checkpoint rate if it won't have any negative impact? For most online systems using INSERT to inject data should be more frequently seen than using COPY.

After INSERT of 512M rows in old file format, i cleared file cache and cold started mapd_server to do the same query. INFO log is attached below. Here is the result, with comparison to alternative file format.
Metadata load time: 208s (vs. 13s)
Fragmenter initialization: 219s (vs. 309s)
Time in Calcite server: 221s (vs. 310s)
Total time: 327s (vs. 347s)
Overall, existing file format delivers better performance.
I'm very curious why the alternative format won ~200s on loading metadata but lost ~100s on fragmenter initialization. Also, how is the total time summed up???
$ tail -f /mnt/trip/mapd/data/mapd_log/mapd_server.INFO
E1012 18:04:27.619213 29994 MapDHandler.cpp:142] This build isn't CUDA enabled, will run on CPU
I1012 18:04:27.619338 29994 DataMgr.cpp:120] cpuSlabSize is 4096M
I1012 18:04:27.623152 29994 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 0ms Epoch: 0 files read: 0 table location: '/mnt/trip/mapd/data/mapd_data/table_0_0/'
I1012 18:04:27.634676 29994 Calcite.cpp:156] Creating Calcite Handler,  Calcite Port is 9093 base data dir is /mnt/trip/mapd/data
I1012 18:04:27.634690 29994 Calcite.cpp:95] Running calcite server as a daemon
I1012 18:04:28.381011 29994 Calcite.cpp:124] Calcite server start took 700 ms
I1012 18:04:28.381088 29994 Calcite.cpp:125] ping took 26 ms
I1012 18:04:28.386425 29994 Calcite.cpp:281] [{"name":"Tan","ret":"double","args":["double"]},{"name":"Truncate__","ret":"float","args":["float","i32"]},{"name":"ln","ret":"double","args":["double"]},{"name":"distance_in_meters__","ret":"double","args":["float","float","float","float"]},{"name":"Floor__","ret":"float","args":["float"]},{"name":"Floor__2","ret":"i32","args":["i32"]},{"name":"Floor__3","ret":"i64","args":["i64"]},{"name":"Truncate","ret":"double","args":["double","i32"]},{"name":"Floor__1","ret":"i16","args":["i16"]},{"name":"radians","ret":"double","args":["double"]},{"name":"degrees","ret":"double","args":["double"]},{"name":"Ceil__","ret":"float","args":["float"]},{"name":"ln__","ret":"double","args":["float"]},{"name":"approx_distance_in_meters","ret":"double","args":["float","float","float","float"]},{"name":"Ceil__2","ret":"i32","args":["i32"]},{"name":"Ceil__1","ret":"i16","args":["i16"]},{"name":"Ceil__3","ret":"i64","args":["i64"]},{"name":"power","ret":"double","args":["double","double"]},{"name":"conv_4326_900913_x","ret":"double","args":["double"]},{"name":"conv_4326_900913_y","ret":"double","args":["double"]},{"name":"Atan","ret":"double","args":["double"]},{"name":"Floor","ret":"double","args":["double"]},{"name":"Log10","ret":"double","args":["double"]},{"name":"Truncate__1","ret":"i16","args":["i16","i32"]},{"name":"Truncate__2","ret":"i32","args":["i32","i32"]},{"name":"Log","ret":"double","args":["double"]},{"name":"Truncate__3","ret":"i64","args":["i64","i32"]},{"name":"Cos","ret":"double","args":["double"]},{"name":"Log__","ret":"double","args":["float"]},{"name":"Log10__","ret":"double","args":["float"]},{"name":"Asin","ret":"double","args":["double"]},{"name":"Cot","ret":"double","args":["double"]},{"name":"Tan__","ret":"double","args":["float"]},{"name":"distance_in_meters","ret":"double","args":["double","double","double","double"]},{"name":"round_to_digit","ret":"double","args":["double","i32"]},{"name":"Atan2","ret":"double","args":["double","double"]},{"name":"Acos","ret":"double","args":["double"]},{"name":"pi","ret":"double","args":[]},{"name":"Sin","ret":"double","args":["double"]},{"name":"Ceil","ret":"double","args":["double"]},{"name":"Exp","ret":"double","args":["double"]}]
E1012 18:04:28.386762 29994 MapDHandler.cpp:174] No GPUs detected, falling back to CPU mode
I1012 18:04:28.386793 29994 MapDHandler.cpp:183] Started in CPU mode
I1012 18:05:27.368151 30015 MapDHandler.cpp:314] User mapd connected to database mapd
I1012 18:05:27.410347 30015 MapDHandler.cpp:2181] select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion;
I1012 18:05:27.417311 30015 Calcite.cpp:247] User mapd catalog mapd sql 'select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion;'
I1012 18:08:56.181397 30017 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 207856ms Epoch: 125234 files read: 506 table location: '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1012 18:09:07.915644 30017 Catalog.cpp:1510] Instantiating Fragmenter for table trips took 219592ms
I1012 18:09:08.082088 30017 Catalog.cpp:1556] Time to load Dictionary 1 was 166ms
I1012 18:09:08.197427 30017 Catalog.cpp:1556] Time to load Dictionary 2 was 115ms
I1012 18:09:08.312327 30017 Catalog.cpp:1556] Time to load Dictionary 3 was 114ms
I1012 18:09:08.434015 30017 Catalog.cpp:1556] Time to load Dictionary 4 was 121ms
I1012 18:09:08.708822 30015 Calcite.cpp:260] Time in Thrift 11 (ms), Time in Java Calcite server 221280 (ms)
I1012 18:09:09.127109 32695 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1012 18:10:16.663326 32701 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1012 18:10:55.029428 30015 MapDHandler.cpp:2279] Total: 327618 (ms), Execution: 327586 (ms)
I1012 18:10:55.063760 30015 MapDHandler.cpp:324] User mapd disconnected from database mapd

@fleapapa The total time is gathered via a stop watch in the outer layer of the query it is not a sum.  It counts total wall clock.
I suspect you are trying to optimize something were we have assumed the bottom layer is SSD so fseek is cheap and you are using HDD trying to do bulk reads.  Ultimately the data needs to get read.
There is no doubt there are gains to be had here but the low hanging fruit in my opinion is around management of old epoch and trying to keep the metadata trim.
I am just in the process of landing a change so a single import creates a single epoch step to reduce the bloat, also allowing a failed load to not leave remnants of the partially processed files.
Thanks for all your review here much appreciated

Ultimately the data needs to get read, but i'm very curious why reading a contiguous layout of the same data set needs 200 seconds more than reading a disjoint one. I will try to figure it out later.

@fleapapa I would have to review what changes you have made in more detail, (when there is a PR).  If you are saying you have moved all the metadata into contiguous single reads then yes that does sound like a bit of mystery.

@dwayneberry. The mystery seemed from too small buffer size of FILE stream (8KB by default).
With larger FILE buffers (256KB), cold start query performance with the alternative file format is significantly improved to 2m8s (from previous 5m47s), as shown in INFO log below:
I1015 14:03:50.586053 21540 MapDServer.cpp:499] MapD started with data directory at '/mnt/trip/mapd/data'
I1015 14:03:50.595965 21540 MapDServer.cpp:506]  Watchdog is set to 1
I1015 14:03:50.595984 21540 MapDServer.cpp:528]  cuda block size 0
I1015 14:03:50.595995 21540 MapDServer.cpp:529]  cuda grid size  0
I1015 14:03:50.596002 21540 MapDServer.cpp:530]  calcite JVM max memory  1024
I1015 14:03:50.596009 21540 MapDServer.cpp:531]  MapD Server Port  9091
I1015 14:03:50.596017 21540 MapDServer.cpp:532]  MapD Calcite Port  9093
I1015 14:03:50.596055 21540 MapDHandler.cpp:132] MapD Server 3.3.1dev-20171015-9825207
E1015 14:03:50.596067 21540 MapDHandler.cpp:139] This build isn't CUDA enabled, will run on CPU
I1015 14:03:50.597515 21540 DataMgr.cpp:120] cpuSlabSize is 4096M
I1015 14:03:50.623394 21540 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 0ms Epoch: 0 files read: 0 table location: '/mnt/trip/mapd/data/mapd_data/table_0_0/'
I1015 14:03:50.626857 21540 Calcite.cpp:156] Creating Calcite Handler,  Calcite Port is 9093 base data dir is /mnt/trip/mapd/data
I1015 14:03:50.626874 21540 Calcite.cpp:95] Running calcite server as a daemon
I1015 14:03:51.365985 21540 Calcite.cpp:124] Calcite server start took 700 ms
I1015 14:03:51.366039 21540 Calcite.cpp:125] ping took 25 ms
I1015 14:03:51.373345 21540 Calcite.cpp:281] [{"name":"Tan","ret":"double","args":["double"]},{"name":"Truncate__","ret":"float","args":["float","i32"]},{"name":"ln","ret":"double","args":["double"]},{"name":"distance_in_meters__","ret":"double","args":["float","float","float","float"]},{"name":"Floor__","ret":"float","args":["float"]},{"name":"Floor__2","ret":"i32","args":["i32"]},{"name":"Floor__3","ret":"i64","args":["i64"]},{"name":"Truncate","ret":"double","args":["double","i32"]},{"name":"Floor__1","ret":"i16","args":["i16"]},{"name":"radians","ret":"double","args":["double"]},{"name":"degrees","ret":"double","args":["double"]},{"name":"Ceil__","ret":"float","args":["float"]},{"name":"ln__","ret":"double","args":["float"]},{"name":"approx_distance_in_meters","ret":"double","args":["float","float","float","float"]},{"name":"Ceil__2","ret":"i32","args":["i32"]},{"name":"Ceil__1","ret":"i16","args":["i16"]},{"name":"Ceil__3","ret":"i64","args":["i64"]},{"name":"power","ret":"double","args":["double","double"]},{"name":"conv_4326_900913_x","ret":"double","args":["double"]},{"name":"conv_4326_900913_y","ret":"double","args":["double"]},{"name":"Atan","ret":"double","args":["double"]},{"name":"Floor","ret":"double","args":["double"]},{"name":"Log10","ret":"double","args":["double"]},{"name":"Truncate__1","ret":"i16","args":["i16","i32"]},{"name":"Truncate__2","ret":"i32","args":["i32","i32"]},{"name":"Log","ret":"double","args":["double"]},{"name":"Truncate__3","ret":"i64","args":["i64","i32"]},{"name":"Cos","ret":"double","args":["double"]},{"name":"Log__","ret":"double","args":["float"]},{"name":"Log10__","ret":"double","args":["float"]},{"name":"Asin","ret":"double","args":["double"]},{"name":"Cot","ret":"double","args":["double"]},{"name":"Tan__","ret":"double","args":["float"]},{"name":"distance_in_meters","ret":"double","args":["double","double","double","double"]},{"name":"round_to_digit","ret":"double","args":["double","i32"]},{"name":"Atan2","ret":"double","args":["double","double"]},{"name":"Acos","ret":"double","args":["double"]},{"name":"pi","ret":"double","args":[]},{"name":"Sin","ret":"double","args":["double"]},{"name":"Ceil","ret":"double","args":["double"]},{"name":"Exp","ret":"double","args":["double"]}]
E1015 14:03:51.381986 21540 MapDHandler.cpp:171] No GPUs detected, falling back to CPU mode
I1015 14:03:51.382210 21540 MapDHandler.cpp:180] Started in CPU mode
I1015 14:04:13.307305 21567 MapDHandler.cpp:311] User mapd connected to database mapd
I1015 14:04:13.339038 21567 MapDHandler.cpp:2178] select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);
I1015 14:04:13.344303 21567 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);'
I1015 14:04:25.290477 21570 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 10967ms Epoch: 126207 files read: 510 table location: '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1015 14:05:44.873132 21570 Catalog.cpp:1511] Instantiating Fragmenter for table trips took 90572ms
I1015 14:05:45.408686 21570 Catalog.cpp:1557] Time to load Dictionary 1 was 535ms
I1015 14:05:45.480578 21570 Catalog.cpp:1557] Time to load Dictionary 2 was 71ms
I1015 14:05:45.531590 21570 Catalog.cpp:1557] Time to load Dictionary 3 was 50ms
I1015 14:05:45.603368 21570 Catalog.cpp:1557] Time to load Dictionary 4 was 71ms
I1015 14:05:45.905020 21567 Calcite.cpp:260] Time in Thrift 12 (ms), Time in Java Calcite server 92548 (ms)
I1015 14:05:45.921736 21567 RelAlgOptimizer.cpp:301] ID=5 (RelProject<140528377411440> (RexInput 1<PHONE_NUMBER>11168)) deleted!
I1015 14:05:45.922024 21567 RelAlgOptimizer.cpp:707] (RelProject<140528377344592> (RexInput 0<PHONE_NUMBER>45328) (RexInput 5<PHONE_NUMBER>45328)) eliminated 1 columns.
I1015 14:05:45.922116 21567 RelAlgOptimizer.cpp:707] (RelAggregate<140528377411168>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1015 14:05:46.259065 24188 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1015 14:06:20.879173 21567 MapDHandler.cpp:2276] Total: 127539 (ms), Execution: 127538 (ms)
I1015 14:06:20.879688 21567 MapDHandler.cpp:321] User mapd disconnected from database mapd

I also applied the same larger FILE buffer size to existing file format. Its cold start performance was improved to 4m30s (from 5m27s).
I1015 07:42:28.057013 19152 MapDServer.cpp:499] MapD started with data directory at '/mnt/trip/mapd/data'
I1015 07:42:28.067157 19152 MapDServer.cpp:506]  Watchdog is set to 1
I1015 07:42:28.067178 19152 MapDServer.cpp:528]  cuda block size 0
I1015 07:42:28.067189 19152 MapDServer.cpp:529]  cuda grid size  0
I1015 07:42:28.067198 19152 MapDServer.cpp:530]  calcite JVM max memory  1024
I1015 07:42:28.067204 19152 MapDServer.cpp:531]  MapD Server Port  9091
I1015 07:42:28.067214 19152 MapDServer.cpp:532]  MapD Calcite Port  9093
I1015 07:42:28.067253 19152 MapDHandler.cpp:132] MapD Server 3.3.1dev-20171015-9825207
E1015 07:42:28.067266 19152 MapDHandler.cpp:139] This build isn't CUDA enabled, will run on CPU
I1015 07:42:28.067566 19152 DataMgr.cpp:120] cpuSlabSize is 4096M
I1015 07:42:28.087728 19152 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 0ms Epoch: 0 files read: 0 table location: '/mnt/trip/mapd/data/mapd_data/table_0_0/'
I1015 07:42:28.099359 19152 Calcite.cpp:156] Creating Calcite Handler,  Calcite Port is 9093 base data dir is /mnt/trip/mapd/data
I1015 07:42:28.099385 19152 Calcite.cpp:95] Running calcite server as a daemon
I1015 07:42:28.311195 19152 Calcite.cpp:124] Calcite server start took 200 ms
I1015 07:42:28.311240 19152 Calcite.cpp:125] ping took 9 ms
I1015 07:42:28.315544 19152 Calcite.cpp:281] [{"name":"Tan","ret":"double","args":["double"]},{"name":"Truncate__","ret":"float","args":["float","i32"]},{"name":"ln","ret":"double","args":["double"]},{"name":"distance_in_meters__","ret":"double","args":["float","float","float","float"]},{"name":"Floor__","ret":"float","args":["float"]},{"name":"Floor__2","ret":"i32","args":["i32"]},{"name":"Floor__3","ret":"i64","args":["i64"]},{"name":"Truncate","ret":"double","args":["double","i32"]},{"name":"Floor__1","ret":"i16","args":["i16"]},{"name":"radians","ret":"double","args":["double"]},{"name":"degrees","ret":"double","args":["double"]},{"name":"Ceil__","ret":"float","args":["float"]},{"name":"ln__","ret":"double","args":["float"]},{"name":"approx_distance_in_meters","ret":"double","args":["float","float","float","float"]},{"name":"Ceil__2","ret":"i32","args":["i32"]},{"name":"Ceil__1","ret":"i16","args":["i16"]},{"name":"Ceil__3","ret":"i64","args":["i64"]},{"name":"power","ret":"double","args":["double","double"]},{"name":"conv_4326_900913_x","ret":"double","args":["double"]},{"name":"conv_4326_900913_y","ret":"double","args":["double"]},{"name":"Atan","ret":"double","args":["double"]},{"name":"Floor","ret":"double","args":["double"]},{"name":"Log10","ret":"double","args":["double"]},{"name":"Truncate__1","ret":"i16","args":["i16","i32"]},{"name":"Truncate__2","ret":"i32","args":["i32","i32"]},{"name":"Log","ret":"double","args":["double"]},{"name":"Truncate__3","ret":"i64","args":["i64","i32"]},{"name":"Cos","ret":"double","args":["double"]},{"name":"Log__","ret":"double","args":["float"]},{"name":"Log10__","ret":"double","args":["float"]},{"name":"Asin","ret":"double","args":["double"]},{"name":"Cot","ret":"double","args":["double"]},{"name":"Tan__","ret":"double","args":["float"]},{"name":"distance_in_meters","ret":"double","args":["double","double","double","double"]},{"name":"round_to_digit","ret":"double","args":["double","i32"]},{"name":"Atan2","ret":"double","args":["double","double"]},{"name":"Acos","ret":"double","args":["double"]},{"name":"pi","ret":"double","args":[]},{"name":"Sin","ret":"double","args":["double"]},{"name":"Ceil","ret":"double","args":["double"]},{"name":"Exp","ret":"double","args":["double"]}]
E1015 07:42:28.315850 19152 MapDHandler.cpp:171] No GPUs detected, falling back to CPU mode
I1015 07:42:28.315876 19152 MapDHandler.cpp:180] Started in CPU mode
I1015 07:43:09.355892 19183 MapDHandler.cpp:311] User mapd connected to database mapd
I1015 07:43:09.404305 19183 MapDHandler.cpp:2178] select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);
I1015 07:43:09.410953 19183 Calcite.cpp:247] User mapd catalog mapd sql 'select count(*) from (select max(pickup_datetime) from trips where medallion = '04D107A378DC761FDA5E92362DCA24E3' group by medallion);'
I1015 07:46:44.071444 19186 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 213691ms Epoch: 125234 files read: 506 table location: '/mnt/trip/mapd/data/mapd_data/table_1_1/'
I1015 07:47:07.352939 19186 Catalog.cpp:1511] Instantiating Fragmenter for table trips took 236986ms
I1015 07:47:07.889114 19186 Catalog.cpp:1557] Time to load Dictionary 1 was 535ms
I1015 07:47:07.977069 19186 Catalog.cpp:1557] Time to load Dictionary 2 was 87ms
I1015 07:47:08.040977 19186 Catalog.cpp:1557] Time to load Dictionary 3 was 63ms
I1015 07:47:08.092468 19186 Catalog.cpp:1557] Time to load Dictionary 4 was 51ms
I1015 07:47:08.426224 19183 Calcite.cpp:260] Time in Thrift 28 (ms), Time in Java Calcite server 238987 (ms)
I1015 07:47:08.465507 19183 RelAlgOptimizer.cpp:301] ID=5 (RelProject<140512069957488> (RexInput 1<PHONE_NUMBER>57216)) deleted!
I1015 07:47:08.466078 19183 RelAlgOptimizer.cpp:707] (RelProject<140512069890640> (RexInput 0<PHONE_NUMBER>91376) (RexInput 5<PHONE_NUMBER>91376)) eliminated 1 columns.
I1015 07:47:08.466164 19183 RelAlgOptimizer.cpp:707] (RelAggregate<140512069957216>(groups: [ 0 ] aggs: [ (RexAgg 2 0 TIMESTAMP NONE 1) ]) eliminated 1 columns.
I1015 07:47:08.829241 21793 BufferMgr.cpp:266] ALLOCATION slab of 8388608 pages<PHONE_NUMBER>B) created in 0 ms CPU_MGR:0
I1015 07:47:39.643321 19183 MapDHandler.cpp:2276] Total: 270238 (ms), Execution: 270220 (ms)
I1015 07:47:39.643931 19183 MapDHandler.cpp:321] User mapd disconnected from database mapd

Here comes another mystery... Why doesn't existing file format benefit from larger FILE buffers the same as alternative file format does??
If necessary, i can create a PR for this tentative change.

@fleapapa Without the PR it is hard to speculate but this probably makes sense as I believe you are now reading large contiguous blocks.  The current format is only reading smaller page headers so maybe does not benefit as much.

@dwayneberry. I tried to create a PR for this. Because prior PR (for COPY compressed files) uses existing file format and is still outstanding, this commit of the tentative file format will mess up the prior PR. What should i do now? Creating a separate branch for this separate PR? Please advise.

@fleapapa yes for the different issue you should have a different branch and PR

@dwayneberry. Sorry, please ignore the PR i created few hours ago. I found it was incomplete so i closed it. Still struggling to create a PR without including others' commits these days...

@dwayneberry,

Without the PR it is hard to speculate but this probably makes sense as I believe you are now reading large contiguous blocks. The current format is only reading smaller page headers so maybe does not benefit as much.

If i understand it correctly, reading page headers occurs before reading data/metadata pages. When reading headers, no fseek makes the difference, but when reading data/metadata pages, the same FILE buffer size should treat the two file formats equally, because data/metadata blocks are stored on almost the same file locations and have the same sizes (2MB and 4KB) for both formats.
An interesting finding from dstat output while running the query is the two "gaps" between the three groups of disk activities (see 7th column below). The two gaps sum up to ~20 seconds (15% of total query time). During the gaps, it is observed that only one cpu core was in use and it was used 100%. So far from gdb i'm still unable to pin down which piece of code was running during the gaps, so not sure if that code can run in parallel.
(My HDD max throughput was measured to be ~150MB/s)
Also, even reading continuous headers, the first group achieved only 1/7 of the HDD max throughput. It should have space for improvement.
dstat output of the tentative format:
  0   0 100   0   0   0| 268k   32k| 126B  362B|   0     0 | 562   623
  0   0  99   0   0   0| 132k   72k| 330B 8418B|   0     0 | 584   615
  0   0  97   3   0   0|   0    36k| 624B 7388B|   0     0 | 542   567
  6   0  83  10   0   0|  10M   48k| 264B 1224B|   0     0 |2457  2968
  8   1  66  26   0   0|  15M   32k| 528B 9644B|   0     0 |2343  2806
  4   1  52  43   0   0|  21M   32k| 370B 8804B|   0     0 |1579  1333
  4   1  56  39   0   0|  21M   44k| 132B  468B|   0     0 |1573  1196
  4   0  52  44   0   0|  21M   32k| 264B 9026B|   0     0 |1355  1259
  4   1  49  47   0   0|  21M   56k| 330B 8396B|   0     0 |1573  1339
  5   0  54  41   0   0|  19M   52k| 132B  468B|   0     0 |1451  1134
  4   1  51  44   0   0|  22M   32k| 396B 8748B|   0     0 |1559  1277
  4   1  49  46   0   0|  23M   32k| 396B 8636B|   0     0 |1358  1261
  4   0  52  43   0   0|  24M   32k| 132B  468B|   0     0 |1381  1209
  5   1  54  39   0   0|  19M   32k| 396B 8412B|   0     0 |1472  1184
  4   1  53  42   0   0|  23M   48k| 132B  468B|   0     0 |1688  1270
  9   0  70  20   0   0|  13M   32k| 396B 8620B|   0     0 |1113   946
 14   0  85   1   0   0|4096B   36k| 330B 7858B|   0     0 | 745   563
 14   0  86   0   0   0|   0    32k| 132B  468B|   0     0 | 892   589
 14   0  85   0   0   0|   0    32k| 198B 1326B|   0     0 |1197   595
 14   0  86   0   0   0|   0    32k| 330B 7506B|   0     0 | 780   574
 14   0  86   0   0   0|   0    32k| 132B  468B|   0     0 | 755   564
 14   0  85   0   0   0|   0    68k| 330B 7042B|   0     0 | 938   595
 15   0  85   0   0   0|   0    32k| 198B 1198B|   0     0 |1150   609
 14   0  85   0   0   0|  16k   32k| 132B  468B|   0     0 | 802   660
  3   0  86  10   0   0|  99M   32k| 258B 1182B|   0     0 |2131  2177
  0   0  87  13   0   0| 123M   36k| 198B 5163B|   0     0 |2525  2625
  0   0  87  13   0   0| 119M   32k| 132B  468B|   0     0 |2418  2518
  0   1  86  13   0   0| 125M   32k| 436B 7870B|   0     0 |2494  2641
  0   0  87  13   0   0| 116M   32k| 396B 8284B|   0     0 |2382  2507
  0   0  87  13   0   0| 111M   32k| 132B  468B|   0     0 |2353  2422
  0   0  86  13   0   0| 108M   32k| 198B  922B|   0     0 |2265  2359
  0   1  86  13   0   0| 116M   32k| 396B 8236B|   0     0 |2343  2437
  0   0  87  13   0   0| 119M   64k| 132B  468B|   0     0 |2357  2468
  0   0  86  13   0   0| 115M   32k| 198B 4848B|   0     0 |2394  2508
  0   0  86  13   0   0| 125M   32k| 396B 7868B|   0     0 |2466  2584
  0   0  86  13   0   0| 114M   32k| 132B  468B|   0     0 |2265  2393
  0   0  87  13   0   0| 123M   32k| 330B 6866B|   0     0 |2403  2520
  0   0  86  13   0   0| 123M   32k| 198B 3728B|   0     0 |2491  2560
  0   0  86  13   0   0| 125M   32k| 132B  468B|   0     0 |2499  2616
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  0   1  86  13   0   0| 117M   32k| 396B 8406B|   0     0 |2360  2487
  0   0  87  13   0   0| 116M   32k| 528B 9062B|   0     0 |2376  2478
  0   0  87  13   0   0| 114M   32k| 132B  468B|   0     0 |2336  2418
  0   1  87  13   0   0| 124M   32k| 396B 8284B|   0     0 |2448  2576
  0   0  86  13   0   0| 116M   36k| 198B  910B|   0     0 |2327  2429
  0   0  87  13   0   0| 118M   32k| 192B  468B|   0     0 |2367  2453
  0   0  87  13   0   0| 126M   32k| 330B 6818B|   0     0 |2572  2629
  0   1  86  13   0   0| 119M   32k| 396B 8668B|   0     0 |2379  2472
  0   0  87  13   0   0| 122M   32k| 132B  468B|   0     0 |2385  2537
  0   0  86  13   0   0| 115M   32k| 396B 8572B|   0     0 |2344  2428
  0   0  87  13   0   0| 127M   32k| 436B 7444B|   0     0 |2501  2581
  0   1  86  13   0   0| 124M   32k| 132B  468B|   0     0 |2365  2479
  0   0  86  13   0   0| 120M   32k| 396B 8316B|   0     0 |2362  2447
  0   0  86  13   0   0| 120M   32k| 396B 8204B|   0     0 |2463  2545
  0   0  87  13   0   0| 105M   32k| 132B  468B|   0     0 |2165  2273
  0   1  86  13   0   0| 108M   32k| 330B 7804B|   0     0 |2190  2300
  0   0  86  13   0   0| 106M   32k| 198B 1182B|   0     0 |2168  2258
  0   0  87  13   0   0| 125M   32k| 132B  468B|   0     0 |2413  2543
  0   0  86  13   0   0| 120M   32k| 396B 7772B|   0     0 |2460  2585
  0   1  86  13   0   0| 128M   32k| 396B 7868B|   0     0 |2524  2680
  0   0  87  13   0   0| 110M   32k| 132B  468B|   0     0 |2274  2389
  0   0  87  13   0   0| 119M   36k| 396B 7980B|   0     0 |2413  2533
  0   1  87  13   0   0| 120M   32k| 396B 8220B|   0     0 |2406  2478
  0   1  86  13   0   0| 115M   32k| 132B  468B|   0     0 |2254  2344
  0   0  87  13   0   0| 117M   52k| 396B 8028B|   0     0 |2302  2376
  0   0  86  13   0   0| 118M   32k| 396B 7820B|   0     0 |2370  2428
  0   0  87  13   0   0| 120M   32k| 132B  468B|   0     0 |2412  2455
  0   1  86  13   0   0| 119M   32k| 396B 7772B|   0     0 |2446  2517
  0   0  87  13   0   0| 114M   32k| 330B 7426B|   0     0 |2299  2390
  0   0  87  13   0   0| 116M   32k| 132B  468B|   0     0 |2397  2461
  0   0  86  13   0   0| 105M   32k| 502B 8238B|   0     0 |2176  2288
  0   0  86  13   0   0| 121M   32k| 132B  468B|   0     0 |2398  2542
  0   0  86  13   0   0| 133M   32k| 198B 1342B|   0     0 |2575  2677
  0   0  86  13   0   0| 121M   32k| 396B 8172B|   0     0 |2396  2473
  0   0  86  13   0   0| 122M   32k| 132B  468B|   0     0 |2460  2557
  0   1  86  13   0   0| 118M   32k| 396B 8140B|   0     0 |2332  2450
  0   0  87  13   0   0| 115M   32k| 396B 8348B|   0     0 |2289  2374
  0   0  87  13   0   0| 123M   32k| 132B  468B|   0     0 |2388  2554
  0   0  86  13   0   0| 117M   32k| 396B 8156B|   0     0 |2372  2425
  0   0  87  13   0   0| 121M   36k| 330B 7394B|   0     0 |2369  2509
  0   0  87  13   0   0| 107M   32k| 132B  468B|   0     0 |2160  2255
  0   0  87  13   0   0| 129M   32k| 330B 7650B|   0     0 |2570  2626
  1   5  86   8   0   0|  69M   32k| 396B 7788B|   0     0 |1697  1704
  2  12  86   0   0   0|   0    32k| 132B  468B|   0     0 | 840   613
  2  12  85   0   0   0|   0    32k| 370B 7428B|   0     0 |1037   641
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  2  12  86   0   0   0|   0    32k| 330B 6812B|   0     0 |1203   581
  2  13  86   0   0   0|   0    32k| 264B 1134B|   0     0 | 965   671
  2  13  85   0   0   0|   0    32k| 330B 7458B|   0     0 | 897   630
  2  12  86   0   0   0|   0    32k| 330B 7330B|   0     0 |1070   582
  3  11  85   0   0   0| 200k   32k|  66B  362B|   0     0 |1238   607
  2  12  86   0   0   0|   0    56k| 436B 8180B|   0     0 | 844   610
  2  12  85   0   0   0|   0    32k| 330B 7970B|   0     0 | 911   608
  2  12  85   0   0   0|   0    32k|  66B  362B|   0     0 |1157   556
  2  12  85   0   0   0|   0    32k| 132B 4278B|   0     0 |1268   621
  3  12  85   0   0   0|   0    72k| 330B 7842B|   0     0 | 836   642
  2  12  85   0   0   0|   0    36k|  66B  362B|   0     0 | 897   584
  4  11  86   0   0   0|   0    36k| 390B 6444B|   0     0 |1034   579
  5   2  74  18   0   1|  19M   32k| 198B 1198B|   0     0 |7433    16k
  2   1  71  26   0   0|  63M   36k| 264B 1128B|   0     0 |1295  1581
  0   0  57  43   0   0| 102M   32k| 462B 9798B|   0     0 | 774   773
  0   1  57  43   0   0| 100M   32k| 396B 9172B|   0     0 | 787   741
  0   0  57  43   0   0|  89M   32k| 126B  378B|   0     0 | 697   656
  0   1  57  43   0   0|  97M   32k| 264B 7416B|   0     0 | 779   790
  1   1  29  69   0   0|  90M   44k| 330B 8818B|   0     0 | 893   867
  0   1  14  85   0   0|  94M   32k|  66B  378B|   0     0 | 784   738
  0   1  14  85   0   0|  94M   32k| 330B 9300B|   0     0 | 689   676
  0   1  17  82   0   0|  95M   32k| 264B 8626B|   0     0 | 733   788
  0   0  36  63   0   0|  93M   32k|  66B  378B|   0     0 | 729   726
  1   1  30  68   0   0|  95M   32k| 436B 8612B|   0     0 |1016   929
  0   0  14  85   0   0|  88M   32k| 330B 8210B|   0     0 | 723   724
  0   1  14  85   0   0|  85M   32k|  66B  378B|   0     0 | 709   747
  0   0  14  85   0   0|  89M   32k| 330B 8754B|   0     0 | 784   775
  0   1  15  84   0   0|  92M   32k| 330B 8338B|   0     0 | 805   741
  1   0  32  67   0   0|  96M   32k|  66B  378B|   0     0 | 866   853
  0   1  14  85   0   0|  91M   36k| 330B 9204B|   0     0 | 741   787
  0   0  14  85   0   0|  89M   32k| 330B 8498B|   0     0 | 697   685
  0   0  14  85   0   0|  90M   32k|  66B  378B|   0     0 | 710   722
  0   0  14  85   0   0|  87M   32k| 330B 7746B|   0     0 | 648   693
  1   0  26  72   0   0|  85M   32k| 330B 8818B|   0     0 | 842   815
  0   1  14  85   0   1|  99M   32k| 132B  468B|   0     0 | 751   717
  0   1  14  85   0   0|  98M   32k| 330B 8578B|   0     0 | 794   733
  0   1  14  85   0   0|  93M   32k| 330B 8114B|   0     0 | 713   728
  0   1  17  82   0   0|  95M   32k|  66B  378B|   0     0 | 738   715
  1   0  51  47   0   0|  98M   32k| 330B 7842B|   0     0 | 907   810
  0   0  29  71   0   0|  92M   32k| 238B 1478B|   0     0 | 764   730
  0   0  29  71   0   0|  88M   60k|  66B  378B|   0     0 | 653   676
  0   1  29  71   0   0|  92M   36k| 330B 8386B|   0     0 | 799   836
  0   0  30  70   0   0|  92M   36k|  66B  378B|   0     0 | 763   723
  1   0  42  56   0   0|  90M   32k| 330B 8130B|   0     0 | 906   840
  0   1  14  85   0   0|  94M   32k| 330B 8594B|   0     0 | 746   757
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  0   0  14  85   0   0|  94M   32k|  66B  484B|   0     0 | 705   746
  0   1  14  85   0   0|  83M   36k| 396B 8706B|   0     0 | 791   780
  0   1  27  72   0   0|  87M   32k| 330B 9156B|   0     0 | 769   744
  1   0  93   6   0   0|  18M   44k| 330B  962B|   0     0 | 704   748
  0   0 100   0   0   0|   0    32k| 528B 9512B|   0     0 | 519   620

Here is the behavior I'm seeing regarding MapD cold starts. For reference, I'm running a single MapD instance (mapd-ee-3.2.4-20171006-6a29a52-Linux-x86_64-render) on a p2.16xlarge (16 GPUs, 64 CPUs, 732 RAM) with a 500GB provisioned IOPS io1 SSD EBS volume attached where the MapD data files are stored. Note that I'm running MapD in a Docker container on ECS. Our database has a single table with 500M rows in it. This data was inserted into this table via COPY stories from from 365 files (a year of data, 1 file per day).
There are 3 scenarios that I've tried:

MapD Docker container dies and is replaced with a new one by ECS on the same EC2 instance.

First query on new container (select count(*) from stories):
mapd_server.INFO output:
I1025 16:26:17.948405   759 MapDHandler.cpp:563] sql_execute :OWRGqZypEweMgy1VaTjXbO0lRdVdB5aU:query_str:select count(*) from stories;
I1025 16:26:17.949635   759 Calcite.cpp:247] User XXXXXXX catalog XXXXXXXX sql 'select count(*) from stories;'
I1025 16:26:18.826992   753 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 198ms Epoch: 5422 files read: 384 table location: '/mapd-storage/data/mapd_data/table_2_1/'
I1025 16:26:19.334791   753 Catalog.cpp:1439] Instantiating Fragmenter for table stories took 706ms
I1025 16:27:29.433676   753 Catalog.cpp:1485] Time to load Dictionary 1 was 70098ms
I1025 16:27:30.373952   753 Catalog.cpp:1485] Time to load Dictionary 2 was 940ms
I1025 16:27:30.434854   753 Catalog.cpp:1485] Time to load Dictionary 3 was 60ms
I1025 16:27:38.713023   753 Catalog.cpp:1485] Time to load Dictionary 4 was 8277ms
I1025 16:28:36.450237   753 Catalog.cpp:1485] Time to load Dictionary 5 was 57736ms
I1025 16:28:36.510403   753 Catalog.cpp:1485] Time to load Dictionary 6 was 59ms
I1025 16:28:36.575469   753 Catalog.cpp:1485] Time to load Dictionary 7 was 64ms
I1025 16:28:36.639046   753 Catalog.cpp:1485] Time to load Dictionary 8 was 63ms
I1025 16:28:36.716979   753 Catalog.cpp:1485] Time to load Dictionary 9 was 77ms
I1025 16:28:41.305037   753 Catalog.cpp:1485] Time to load Dictionary 10 was 4587ms
I1025 16:28:41.371887   753 Catalog.cpp:1485] Time to load Dictionary 11 was 66ms
I1025 16:28:41.450786   753 Catalog.cpp:1485] Time to load Dictionary 12 was 78ms
I1025 16:28:41.517796   753 Catalog.cpp:1485] Time to load Dictionary 13 was 66ms
I1025 16:28:41.591336   753 Catalog.cpp:1485] Time to load Dictionary 14 was 73ms
I1025 16:28:41.654145   753 Catalog.cpp:1485] Time to load Dictionary 15 was 62ms
I1025 16:28:42.043650   753 Catalog.cpp:1485] Time to load Dictionary 16 was 389ms
I1025 16:28:42.228368   759 Calcite.cpp:260] Time in Thrift 12 (ms), Time in Java Calcite server 144266 (ms)
I1025 16:28:44.639158 119357 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 71 ms GPU_MGR:15
I1025 16:28:44.640264 119364 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:1
I1025 16:28:44.641014 119362 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 69 ms GPU_MGR:10
I1025 16:28:44.641609 119366 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 66 ms GPU_MGR:3
I1025 16:28:44.642930 119365 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 67 ms GPU_MGR:2
I1025 16:28:44.643682 119360 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:12
I1025 16:28:44.644219 119359 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:13
I1025 16:28:44.645932 119367 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 70 ms GPU_MGR:4
I1025 16:28:44.647936 119361 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 72 ms GPU_MGR:11
I1025 16:28:44.649992 119363 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 73 ms GPU_MGR:0
I1025 16:28:44.652099 119369 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 71 ms GPU_MGR:6
I1025 16:28:44.654297 119358 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 73 ms GPU_MGR:14
I1025 16:28:44.657061 119368 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 76 ms GPU_MGR:5
I1025 16:28:44.658774 119371 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 78 ms GPU_MGR:8
I1025 16:28:44.660782 119370 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 80 ms GPU_MGR:7
I1025 16:28:44.662900 119372 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 82 ms GPU_MGR:9
I1025 16:28:44.666066   759 MapDHandler.cpp:575] sql_execute-COMPLETED Total: 146717 (ms), Execution: 146716 (ms)

2.44 minutes to recover from a cold start.

EC2 instance dies. Spin up a new EC2 instance attaching the original EBS volume to the new instance.

First query on new instance (select count(*) from stories):
mapd_server.INFO output:
I1025 16:13:45.529206   759 MapDHandler.cpp:563] sql_execute :hBjhHPnQL7KddvNQuimjatNuIkSojN6P:query_str:select count(*) from stories;
I1025 16:13:45.530330   759 Calcite.cpp:247] User XXXXXXXX catalog XXXXXXXX sql 'select count(*) from stories;'
I1025 16:13:49.613662   753 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 3478ms Epoch: 5422 files read: 384 table location: '/mapd-storage/data/mapd_data/table_2_1/'
I1025 16:13:50.147068   753 Catalog.cpp:1439] Instantiating Fragmenter for table stories took 4013ms
I1025 16:15:25.993432   753 Catalog.cpp:1485] Time to load Dictionary 1 was 95846ms
I1025 16:15:26.998808   753 Catalog.cpp:1485] Time to load Dictionary 2 was 1005ms
I1025 16:15:27.058037   753 Catalog.cpp:1485] Time to load Dictionary 3 was 59ms
I1025 16:15:37.544963   753 Catalog.cpp:1485] Time to load Dictionary 4 was 10486ms
I1025 16:18:49.061210   753 Catalog.cpp:1485] Time to load Dictionary 5 was 191515ms
I1025 16:18:49.137368   753 Catalog.cpp:1485] Time to load Dictionary 6 was 75ms
I1025 16:18:49.216290   753 Catalog.cpp:1485] Time to load Dictionary 7 was 78ms
I1025 16:18:49.293462   753 Catalog.cpp:1485] Time to load Dictionary 8 was 76ms
I1025 16:18:49.373011   753 Catalog.cpp:1485] Time to load Dictionary 9 was 79ms
I1025 16:18:55.125483   753 Catalog.cpp:1485] Time to load Dictionary 10 was 5752ms
I1025 16:18:55.200206   753 Catalog.cpp:1485] Time to load Dictionary 11 was 74ms
I1025 16:18:55.279639   753 Catalog.cpp:1485] Time to load Dictionary 12 was 79ms
I1025 16:18:55.351475   753 Catalog.cpp:1485] Time to load Dictionary 13 was 71ms
I1025 16:18:55.447755   753 Catalog.cpp:1485] Time to load Dictionary 14 was 96ms
I1025 16:18:55.533304   753 Catalog.cpp:1485] Time to load Dictionary 15 was 85ms
I1025 16:18:55.939312   753 Catalog.cpp:1485] Time to load Dictionary 16 was 405ms
I1025 16:18:56.119817   759 Calcite.cpp:260] Time in Thrift 13 (ms), Time in Java Calcite server 310576 (ms)
I1025 16:18:58.458586 119365 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:15
I1025 16:18:58.459600 119378 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:7
I1025 16:18:58.460345 119366 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 67 ms GPU_MGR:14
I1025 16:18:58.460768 119380 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 67 ms GPU_MGR:9
I1025 16:18:58.461941 119367 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 67 ms GPU_MGR:13
I1025 16:18:58.462613 119379 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:8
I1025 16:18:58.463224 119368 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:12
I1025 16:18:58.465059 119369 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 70 ms GPU_MGR:11
I1025 16:18:58.467001 119370 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 72 ms GPU_MGR:10
I1025 16:18:58.468988 119371 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 74 ms GPU_MGR:0
I1025 16:18:58.470746 119372 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 75 ms GPU_MGR:1
I1025 16:18:58.472645 119373 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 77 ms GPU_MGR:2
I1025 16:18:58.475143 119374 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 79 ms GPU_MGR:3
I1025 16:18:58.478296 119377 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 79 ms GPU_MGR:6
I1025 16:18:58.480962 119375 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 81 ms GPU_MGR:4
I1025 16:18:58.482516 119376 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 83 ms GPU_MGR:5
I1025 16:18:58.485944   759 MapDHandler.cpp:575] sql_execute-COMPLETED Total: 312956 (ms), Execution: 312955 (ms)

5.2 minutes to recover from a cold start.

EC2 instance dies. Spin up a new one using a snapshot of the original EBS volume.

First query on new instance (select count(*) from stories):
mapd_server.INFO output:
I1025 14:17:58.340020   752 MapDHandler.cpp:563] sql_execute :ktrxrfI5dvQbCeb5g1gKeCBmty30Hyq6:query_str:select count(*) from stories;
I1025 14:17:58.341074   752 Calcite.cpp:247] User XXXXXXXX catalog XXXXXXXX sql 'select count(*) from stories;'
I1025 14:30:33.478854   753 FileMgr.cpp:173] Completed Reading table's file metadata, Elasped time : 754495ms Epoch: 5422 files read: 384 table location: '/mapd-storage/data/mapd_data/table_2_1/'
I1025 14:30:34.041771   753 Catalog.cpp:1439] Instantiating Fragmenter for table stories took 755059ms
I1025 15:06:34.123471   753 Catalog.cpp:1485] Time to load Dictionary 1 was 2160081ms
I1025 15:06:53.713860   753 Catalog.cpp:1485] Time to load Dictionary 2 was 19590ms
I1025 15:06:54.260835   753 Catalog.cpp:1485] Time to load Dictionary 3 was 546ms
I1025 15:10:11.661267   753 Catalog.cpp:1485] Time to load Dictionary 4 was 197400ms
I1025 15:52:10.420193   753 Catalog.cpp:1485] Time to load Dictionary 5 was 2518758ms
I1025 15:52:11.032282   753 Catalog.cpp:1485] Time to load Dictionary 6 was 611ms
I1025 15:52:11.556306   753 Catalog.cpp:1485] Time to load Dictionary 7 was 523ms
I1025 15:52:12.270228   753 Catalog.cpp:1485] Time to load Dictionary 8 was 713ms
I1025 15:52:12.702174   753 Catalog.cpp:1485] Time to load Dictionary 9 was 431ms
I1025 15:54:09.367240   753 Catalog.cpp:1485] Time to load Dictionary 10 was 116664ms
I1025 15:54:09.882225   753 Catalog.cpp:1485] Time to load Dictionary 11 was 514ms
I1025 15:54:10.461156   753 Catalog.cpp:1485] Time to load Dictionary 12 was 578ms
I1025 15:54:10.965718   753 Catalog.cpp:1485] Time to load Dictionary 13 was 504ms
I1025 15:54:11.723712   753 Catalog.cpp:1485] Time to load Dictionary 14 was 757ms
I1025 15:54:12.252774   753 Catalog.cpp:1485] Time to load Dictionary 15 was 528ms
I1025 15:54:19.983253   753 Catalog.cpp:1485] Time to load Dictionary 16 was 7730ms
I1025 15:54:20.201068   752 Calcite.cpp:260] Time in Thrift 14 (ms), Time in Java Calcite server 5781845 (ms)
I1025 15:54:22.635879 119358 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 57 ms GPU_MGR:14
I1025 15:54:22.650288 119359 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:13
I1025 15:54:22.651144 119361 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:11
I1025 15:54:22.651751 119357 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 69 ms GPU_MGR:15
I1025 15:54:22.652956 119362 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 70 ms GPU_MGR:10
I1025 15:54:22.653822 119360 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 67 ms GPU_MGR:12
I1025 15:54:22.654538 119366 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 67 ms GPU_MGR:3
I1025 15:54:22.657059 119363 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 69 ms GPU_MGR:0
I1025 15:54:22.659615 119364 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 68 ms GPU_MGR:1
I1025 15:54:22.661696 119367 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 70 ms GPU_MGR:4
I1025 15:54:22.664885 119365 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 73 ms GPU_MGR:2
I1025 15:54:22.666936 119368 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 75 ms GPU_MGR:5
I1025 15:54:22.668931 119370 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 77 ms GPU_MGR:7
I1025 15:54:22.671362 119372 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 79 ms GPU_MGR:9
I1025 15:54:22.673399 119371 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 78 ms GPU_MGR:8
I1025 15:54:22.675407 119369 BufferMgr.cpp:266] ALLOCATION slab of 4194304 pages<PHONE_NUMBER>B) created in 80 ms GPU_MGR:6
I1025 15:54:22.679028   752 MapDHandler.cpp:575] sql_execute-COMPLETED Total: 5784338 (ms), Execution: 5784337 (ms)

96 minutes (!) to recover from a cold start.
Note: I did not initialize the EBS volume first. You probably want to initialize the EBS volume first. :-) (http://docs.aws.amazon.com/AWSEC2/latest/UserGuide/ebs-initialize.html)
I suspect the few minutes difference between the times seen between a new Docker container on the same instance vs. a brand new instance is due to OS level file caching on the host.
Hope this is helpful.

Hi,
From your final comment I assume you understand that the cost you are seeing on scenario 3 is the overhead of downloading the data from s3 to the local disk so I am not going to worry too much about the timing there, as I assume you recognize it is not something in our control.
The two other cases are both the same I would suspect (as you noted) basically with and without OS file system caching.  So with the additional logs you have shared I can see you have two large dictionaries in your system.
Time to load Dictionary 1 was 95,846 ms
Time to load Dictionary 5 was 191,515 ms

These two dictionaries are taking up the bulk of your cold start time.
Hacky way to look at content of dictionary here would be to go to your data directory and :
less mapd_data/DB_1_DICT_1/DictPayLoad

Hopefully you will be able to tell which column is generating this data
do the same for dictionary 5
After identifying the column a couple of questions
Do these columns really need to be dictionary encoded?
Are they part of an array?
Are they needed to be grouped by
It is likely there are a large number of non unique items in these dictionary columns.
Once we have insight into how you use these columns we can explore next steps
regards

@dwayneberry yup, completely understand regarding scenario 3. I just wanted to be thorough with all possible scenarios in case that helps others.
As for dictionaries, you're right, the big one (dictionary 5) will NOT be grouped by, and thus doesn't need to be dictionary encoded at all! It looks like our DDL omitted the encoding for this column, and thus we got the default DICT encoding. Thanks for the tip! I will definitely be reviewing our DDL to make sure we're not unnecessarily using dictionary encoding when we don't need it.
Thanks again.

@dwayneberry is there a way to tell how much memory a specific dictionary is taking up? i.e. when we delete this offender, obviously disk space usage will decrease significantly, but wondering if it means we can fit more data from the database into memory as a result as well.
Thanks.

Hi
The disk space will remain approximately the same.  The text columns still need to be stored on disk they just wont be encoded to Dictionary.
The CPU in-memory footprint (assuming the row is being referenced in a sql query) overall will go down by the dictionary overhead which is in the order of rows x 4 bytes
regards

@dwayneberry ah ok. thanks.

@fleapapa It feels like this issue can be closed, please confirm

Yes, from discussions above, this issue, in two occurrences, seemed all due to memory constraints. Once the constraints were relaxed, the issue seemed gone.


In android Using still using FlutterActivity  instead of FlutterFragmentActivity  in MainActivity.kt:

Describe the bug
If we using stripe package and this barcode scanner package then its creating problem because stripe package works with FlutterFragmentActivity and scanner package doesn't work with that
To Reproduce
Steps to reproduce the behavior:

Go to '...'
Click on '....'
Scroll down to '....'
See error

Expected behavior
A clear and concise description of what you expected to happen.
Screenshots
If applicable, add screenshots to help explain your problem.
Smartphone (please complete the following information):

Device: [e.g. iPhone6]
OS: [e.g. iOS8.1]
Browser [e.g. stock browser, safari]
Version [e.g. 22]

Additional context
Add any other context about the problem here.

any news here?