S/4 HANA Performance on SAS versus SSD drives

This will be our second performance workbench testing: How will I/O performance impact the HANA performance?

What we currently have:

HANA DB 1.0 SPS11.2 running on 10k RPM SAS drives RAID 1

To be able to confirm that, we'll need to login to the server IMM to take a look

These are the seagate 6Gb/s drives, as per the review by http://www.storagereview.com/seagate_enterprise_performance_10k_hdd_savvio_10k6_review,

• the sustained throughput is averaged at 204MB/s
• Sustained Transfer Rate Outer to Inner Diameter: 204 to 125MB/s

Talking about HANA performance, we'll have to look at, for example, HANA startup, shutdown or running data performance.

For HANA shutdown, when we look at the index server logs, it took 1.5 minutes, from 15:43:03 to 15:44:34

[2577]{-1}[-1/-1] 2016-04-30 15:43:03.995803 i Service_Shutdown TrexService.cpp(00803) : Preparing for shutting service down
[3081]{-1}[-1/-1] 2016-04-30 15:43:03.996401 i Service_Shutdown TREXIndexServer.cpp(04329) : Triggering timezone checker shutdown
[3081]{-1}[-1/-1] 2016-04-30 15:43:03.996427 i assign           TREXIndexServer.cpp(04339) : unassign from volume 3
[3081]{-1}[-1/-1] 2016-04-30 15:43:03.996431 i Service_Shutdown TREXIndexServer.cpp(04342) : Preparing to shutdown
[3081]{-1}[-1/-1] 2016-04-30 15:43:03.996433 i Service_Shutdown TREXIndexServer.cpp(04350) : stopping statistics server worker threads
[3093]{-1}[-1/-1] 2016-04-30 15:43:04.126564 i TraceContext     TraceContext.cpp(00878) : UserName=
[3093]{-1}[-1/-1] 2016-04-30 15:43:04.126536 i Service_Startup  TREXIndexServer.cpp(02027) : Pre-/Re-Loading of column store tables finished.
[3081]{-1}[-1/-1] 2016-04-30 15:43:04.996706 i Service_Shutdown TREXIndexServer.cpp(04376) : stopping dynamic range partitioning
[3081]{-1}[-1/-1] 2016-04-30 15:43:04.996978 i Service_Shutdown TREXIndexServer.cpp(04382) : stopping federation statistics collection
[3081]{-1}[-1/-1] 2016-04-30 15:43:04.997089 i Service_Shutdown TREXIndexServer.cpp(04386) : stopping extended storage heartbeat thread
[3081]{-1}[-1/-1] 2016-04-30 15:43:05.002930 i Service_Shutdown TREXIndexServer.cpp(04417) : Abort logreplay
[3081]{-1}[-1/-1] 2016-04-30 15:43:05.002954 i Service_Shutdown TREXIndexServer.cpp(04422) : Stopping LOBGarbageCollectorThread
[3081]{-1}[-1/-1] 2016-04-30 15:43:05.003225 i Service_Shutdown TREXIndexServer.cpp(04446) : Stopping EPM
[3081]{-1}[-1/-1] 2016-04-30 15:43:05.099974 i Service_Shutdown TREXIndexServer.cpp(04450) : Stopping Embedded Catalyst Services
[3081]{-1}[-1/-1] 2016-04-30 15:43:06.192210 i Service_Shutdown TREXIndexServer.cpp(04455) : Stopping PlanningEngine
[3081]{-1}[-1/-1] 2016-04-30 15:43:06.322184 i Service_Shutdown TREXIndexServer.cpp(04462) : Stopping SQL session service
[3081]{-1}[-1/-1] 2016-04-30 15:43:06.322323 i Service_Shutdown tcp_listener.h(00119) : Shutdown SqlListener service
[3081]{-1}[-1/-1] 2016-04-30 15:43:06.518066 i Service_Shutdown TREXIndexServer.cpp(04466) : Stopping SQL plan cache
[3081]{-1}[-1/-1] 2016-04-30 15:43:08.379483 i Service_Shutdown TREXIndexServer.cpp(04472) : Stopping QueueServer...
[3081]{-1}[-1/-1] 2016-04-30 15:43:08.381251 i Service_Shutdown TREXIndexServer.cpp(04478) : Stopping PlanViz
[3081]{-1}[-1/-1] 2016-04-30 15:43:11.882610 i Service_Shutdown TREXIndexServer.cpp(04505) : Stopping TRexApiSystem
[3081]{-1}[-1/-1] 2016-04-30 15:43:11.883159 i Service_Shutdown TREXIndexServer.cpp(04509) : Stopping executor
[3081]{-1}[-1/-1] 2016-04-30 15:43:11.883442 i Service_Shutdown TREXIndexServer.cpp(04513) : Stopping DebuggingBackend
[3081]{-1}[-1/-1] 2016-04-30 15:43:11.883745 i Service_Shutdown TREXIndexServer.cpp(04517) : Stopping CalculationEngineManager
[3081]{-1}[-1/-1] 2016-04-30 15:43:11.884061 i Service_Shutdown TREXIndexServer.cpp(04521) : Stopping TaskManager
[3081]{-1}[-1/-1] 2016-04-30 15:43:11.884132 i Service_Shutdown TREXIndexServer.cpp(04525) : Stopping TaskStatisticsManager
[3081]{-1}[-1/-1] 2016-04-30 15:43:11.884174 i Service_Shutdown TREXIndexServer.cpp(04529) : Stopping CacheMgr
[3081]{-1}[-1/-1] 2016-04-30 15:43:12.461571 i Service_Shutdown TREXIndexServer.cpp(04536) : Stopping GraphEngineMgr
[3081]{-1}[-1/-1] 2016-04-30 15:43:12.462211 i Service_Shutdown TREXIndexServer.cpp(04540) : Stopping Invalidator
[3081]{-1}[-1/-1] 2016-04-30 15:43:12.462379 i Service_Shutdown TREXIndexServer.cpp(04544) : Stopping RClient
[3081]{-1}[-1/-1] 2016-04-30 15:43:12.462600 i Service_Shutdown TREXIndexServer.cpp(04548) : Stopping SAMLFactory
[3081]{-1}[-1/-1] 2016-04-30 15:43:12.465840 i Service_Shutdown TREXIndexServer.cpp(04553) : Stopping VSI runtime
[3081]{-1}[-1/-1] 2016-04-30 15:43:12.523414 i Service_Shutdown TREXIndexServer.cpp(04559) : Unassigning all tables
[3081]{-1}[-1/-1] 2016-04-30 15:43:12.920668 i Service_Shutdown TREXIndexServer.cpp(06570) : Starting unloading of 22084 tables with 8 parallel threads (2760 tables per thread)
[3081]{-1}[-1/-1] 2016-04-30 15:44:14.426976 i Service_Shutdown TREXIndexServer.cpp(06605) : Finished table unloading
[3081]{-1}[-1/-1] 2016-04-30 15:44:14.427679 i Service_Shutdown TREXIndexServer.cpp(04567) : Stopping udivmgr
[3081]{-1}[-1/-1] 2016-04-30 15:44:14.431766 i Service_Shutdown TREXIndexServer.cpp(04573) : Closing trace files
[3081]{-1}[-1/-1] 2016-04-30 15:44:14.431787 i Service_Shutdown TREXIndexServer.cpp(04577) : Stopping persistenceLayer
[3081]{-1}[-1/-1] 2016-04-30 15:44:14.433569 i Service_Shutdown TREXIndexServer.cpp(04596) : Stopping joinengine
[3081]{-1}[-1/-1] 2016-04-30 15:44:15.420972 i Service_Shutdown garbage_lob_file_handler.cc(00326) : ptime::GarbageLobFileHandler close
[3081]{-1}[-1/-1] 2016-04-30 15:44:15.735154 i Service_Shutdown garbage_lob_file_handler.cc(00344) : ptime::GarbageLobFileHandler close finished
[3081]{-1}[-1/-1] 2016-04-30 15:44:15.740653 i Service_Shutdown transmgmt.cc(05904) : Preparing for TransactionManager shutdown
[3081]{-1}[-1/-1] 2016-04-30 15:44:16.740975 i Service_Shutdown transmgmt.cc(09222) : Cleaning up active transactions starts
[3081]{-1}[-1/-1] 2016-04-30 15:44:16.741315 i Service_Shutdown transmgmt.cc(09384) : Cleaning up active transactions finished:0 leftover transactions handled
[3081]{-1}[-1/-1] 2016-04-30 15:44:16.750257 i Service_Shutdown SmFastRestart.cc(00232) : Keeping RS shared memory at RowStore shutdown
[3081]{-1}[-1/-1] 2016-04-30 15:44:16.862894 i Service_Shutdown SmFastRestart.cc(00285) : Preconditions for reuse of RS shared memory are not satisfied. Found remaining version(s).
[3081]{-1}[-1/-1] 2016-04-30 15:44:16.862957 i Service_Shutdown SmFastRestart.cc(00286) : Persistency will be used for RowStore segments at next service startup
[3081]{-1}[-1/-1] 2016-04-30 15:44:16.863131 i PersistenceManag PersistenceManagerImpl.cpp(07579) : PersistenceManager::shutdown started...
[3081]{-1}[-1/-1] 2016-04-30 15:44:29.467055 i Logger           BackupHandlerImpl.cpp(00342) : Shutting down log backup, 0 log backup(s) pending
[3081]{-1}[-1/-1] 2016-04-30 15:44:33.523581 i PersistenceManag PersistenceManagerImpl.cpp(07748) : PersistenceManager::shutdown finished.
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.226658 i Service_Shutdown TrexService.cpp(00866) : Disabling signal handler
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.226690 i Service_Shutdown TrexService.cpp(00880) : Stopping self watchdog
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.226862 i Service_Shutdown TrexService.cpp(00892) : Stopping request dispatcher
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.226878 i Service_Shutdown TrexService.cpp(00899) : Stopping responder
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.227444 i Service_Shutdown TrexService.cpp(00906) : Stopping channel waiter
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.227483 i Service_Shutdown TrexService.cpp(00911) : Shutting service down
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.227491 i Service_Shutdown TREXIndexServer.cpp(04640) : Stopping libxml
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.905856 i Service_Shutdown TrexService.cpp(00916) : Stopping threads
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.908085 i Service_Shutdown TrexService.cpp(00921) : Stopping communication
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915187 i Service_Shutdown TrexService.cpp(00938) : Deleting self watchdog
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915236 i Service_Shutdown TrexService.cpp(00946) : Deleting request dispatcher
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915276 i Service_Shutdown TrexService.cpp(00954) : Deleting responder
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915447 i Service_Shutdown TrexService.cpp(00962) : Deleting service
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915531 i Service_Shutdown TrexService.cpp(00969) : Deleting threads
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915533 i Service_Shutdown TrexService.cpp(00975) : Deleting pools
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915560 i Service_Shutdown TrexService.cpp(00985) : Deleting configuration
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.915562 i Service_Shutdown TrexService.cpp(00989) : Removing pidfile
[2577]{-1}[-1/-1] 2016-04-30 15:44:34.916187 i Service_Shutdown TrexService.cpp(01026) : System down

For starting up, we know that even after all services are up and running, but HDB still need to load all the tables into memory, which took a huge amount of time

For index server startup, including loading column stores, it took almost 20 minutes, from 16:23 to 16:44

[8677]{-1}[-1/-1] 2016-04-30 16:23:18.663039 i Basis            TraceStream.cpp(00457) : ==== Starting hdbindexserver, version 1.00.112.02.1459851171 (fa/newdb100_rel), build linuxx86_64 eab796515941b44fd4838ceae3b5571999dc1d87 2016-04-05 12:25:18 ld7272 gcc (SAP release 20150717, based on SUSE gcc48-4.8.3+r212056-6.3) 4.8.3 20140627 [gcc-4_8-branch revision 212064]
[8677]{-1}[-1/-1] 2016-04-30 16:23:18.663224 i Basis            TraceStream.cpp(00459) : MaxOpenFiles: 1048576
[8677]{-1}[-1/-1] 2016-04-30 16:23:18.663268 i Basis            TraceStream.cpp(00461) : Server Mode: L2 Delta
[8677]{-1}[-1/-1] 2016-04-30 16:23:18.663283 i Basis            ProcessorInfo.cpp(00732) : Using GDT segment limit to determine current CPU ID
[8677]{-1}[-1/-1] 2016-04-30 16:23:18.663284 i Basis            Timer.cpp(00642) : Using RDTSC for HR timer
[8677]{-1}[-1/-1] 2016-04-30 16:23:18.663287 i Memory           AllocatorImpl.cpp(01349) : Allocators activated
[8677]{-1}[-1/-1] 2016-04-30 16:23:18.663289 i Memory           AllocatorImpl.cpp(01365) : Using big block segment size 16777216
[8677]{-1}[-1/-1] 2016-04-30 16:23:18.676819 w Environment      Environment.cpp(00375) : Changing environment set SSL_WITH_OPENSSL=0
[8677]{-1}[-1/-1] 2016-04-30 16:23:19.686084 i Service_Startup  sm_manager.cc(00297) : General SqlListener is selected
[8737]{-1}[-1/-1] 2016-04-30 16:23:19.866885 i assign           TREXIndexServer.cpp(01039) : assign to volume 3 started
...
...
...

[9425]{-1}[-1/-1] 2016-04-30 16:44:46.382390 i TraceContext     TraceContext.cpp(00878) : UserName=
[9425]{-1}[-1/-1] 2016-04-30 16:44:46.382374 i Service_Startup  TREXIndexServer.cpp(02027) : Pre-/Re-Loading of column store tables finished.

As planned we also need to do a dummy client copy testing to see how the HANA DB performs. We did not choose SAP_ALL since we don't want to wait too long. 'Test run' only, from client 100 copied to client 600

To be fair we choose app server 1 to run this client copy simulation. So that when we migrate everything from SAS to SSD we'll do the same again

Ready to run

Client copy test run begins

Actual starts, pay attention to the number of tables, in total 82905 tables

Check the current HANA DB from OS level, as you can see CPUs are busy, hard drives are busy, not only read, but also write (to logs?)

One thing we notice was, when the system doing client copy simulation, but not real run, the memory usage does not grow.

Client copy ends up with errors due to out of memory.... Will catch the screen via SCC3

Now we start the migration of HANA DB, from SAS to the new Samsung EVO850 SSD

Migrating from ESXi, we notice that the speed is constantly at only around 75MB/s, read/write, which is much lower than the SAS declared 125MB/s. We think the bottle net would be the SAS RAID1 read, but, only 75MB/s?

Finally the HANA DB migration is finished. To be able to fair, we would like to see how's the SSD read performance in the VM level. So we started a VM clone, to a RAID5 SATA

Holy cow we got more than 300MB/s read/write speed, which is 400% increse compared to the SAS RAID1! The whole cloing process only takes 8 minutes! This means, with fast enough drives, the traditional 'backup' method is kind of out, simply schedule a VM clone will do the work perfectly!

Now we start HANA DB. From the moment when I looked at the I/O, it's really a big jump compared to the older way SAS drives. If I recall correctly, before we've never seen anything greater than 50MB/s for HDB startup, but now, average 150MB/s

Finally today we had a chance to do another client copy emulation, after the HANA DB migrated to SSD.

Let's take a look at the result.

• When the HANA DB was running on SAS drives, it copied about 5.8 million records, and took about 56 minutes

• Now the HANA DB was running on SSD, it also copied about 5.8 million records, and took about 42 minutes.

The difference is about 33% faster!

Let's compare the HANA DB startup time. When HANA is running in SSD, the startup log shows:

22:02:11.442093 i Basis            TraceStream.cpp(00457) : ==== Starting hdbindexserver, version 1.00.112.02.1459851171 (fa/newdb100_rel), build linuxx86_64 eab796515941b44fd4838ceae3b5571999dc1d87 2016-04-05 12:25:18 ld7272 gcc (SAP release 20150717, based on SUSE gcc48-4.8.3+r212056-6.3) 4.8.3 20140627 [gcc-4_8-branch revision 212064]
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.442331 i Basis            TraceStream.cpp(00459) : MaxOpenFiles: 1048576
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.442392 i Basis            TraceStream.cpp(00461) : Server Mode: L2 Delta
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.442410 i Basis            ProcessorInfo.cpp(00732) : Using GDT segment limit to determine current CPU ID
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.442412 i Basis            Timer.cpp(00642) : Using RDTSC for HR timer
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.442417 i Memory           AllocatorImpl.cpp(01349) : Allocators activated
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.442418 i Memory           AllocatorImpl.cpp(01365) : Using big block segment size 16777216
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.459256 w Environment      Environment.cpp(00375) : Changing environment set SSL_WITH_OPENSSL=0
[2636]{-1}[-1/-1] 2016-05-10 22:02:11.937308 i Service_Startup  sm_manager.cc(00297) : General SqlListener is selected
[2684]{-1}[-1/-1] 2016-05-10 22:02:12.148357 i assign           TREXIndexServer.cpp(01039) : assign to volume 3 started
...
...

 22:05:45.810841 i TraceContext     TraceContext.cpp(00878) : UserName=
[3089]{-1}[-1/-1] 2016-05-10 22:05:45.810831 i Service_Startup  TREXIndexServer.cpp(02027) : Pre-/Re-Loading of column store tables finished.

The total time is 3:34. Compared to what we had SAS drives which took almost 20 minutes, the performance increment is... 600%!!!