Errors in dbsrver VM when loaddb_postgres.sh is executed

[lroderic]

You're having problems with both appserver and webserver (https://www.spec.org/forums/index.php?topic=89.msg557#msg557), so let's get one workload working before adding more. I'm not clear if you can even run one tile at this point.

Set NUM_WORKLOADS=1 for now to run only appserver. Can you run successfully two tiles (two appservers against one dbserver)? Are you restoring the dbserver database between runs? After you restore the database, what do you see when you log into appserver and run jApp-testappserver.sh in the helper directory:

Code: [Select]

echo "Stopping Appserver (will fail if already stopped)"
ssh specdelivery -n 'cd /opt/SPECjAppServer2004/bin;./appsrv-ctrl.sh stop'
echo
echo "Stopping Emulator (will fail if already stopped)"
ssh specemulator -n 'cd /opt/SPECjAppServer2004/bin;./tomcat-ctrl.sh stop'

sleep 5

echo "Starting Appserver"
ssh specdelivery -n 'cd /opt/SPECjAppServer2004/bin;./appsrv-ctrl.sh start'

echo "Starting Emulator"
ssh specemulator -n 'cd /opt/SPECjAppServer2004/bin;./tomcat-ctrl.sh start'

echo; echo "Test Emulator - should show 200 OK"
curl http://specemulator:8080/Emulator/EmulatorServlet?cmd=switchlog

echo; echo "Test Delivery - should show 200 OK"
curl http://specdelivery:8000/Supplier/DeliveryServlet?cmd=switchlog

echo; echo "Test Appserver - should show three tests PASSED if"
echo; echo "database is up. Rerun this script after dbserver is set up."
read -p "Press Enter to continue..."
curl http://specdelivery:8000/SPECjAppServer/app?action=atomicityTests

Lisa

[Miles]

Hi
I set the value of LOAD_SCALE_FACTORS="0.1"  to run with 5-Tile_4-workload, but errors appeared.
Before executing, I have run jAppInitRstr.sh on client1 and client5; jAppInit.sh on client2~client4.

primectrl.out
...
-09-28 02:47:06:955 PrimeControl: waiting for 1 masters to finish
2017-09-28 02:47:21:955 PrimeControl: waiting for 1 masters to finish
2017-09-28 02:47:36:956 PrimeControl: [ERROR] Maximum prime client wait time exceeded!
2017-09-28 02:55:04:590 PrimeControl: client1:1098 (PRIME_HOST[0][0]) run complete; numStarted = 0
2017-09-28 02:55:04:594 Workload validation errors reported!:
2-1-0 = Weighted percentage difference (2.60%) for home in Iteration 1 is too high. Expected: 15657 requests, Actual: 10642

2-1-1 = Weighted percentage difference (4.13%) for search in Iteration 1 is too high. Expected: 24358 requests, Actual: 16389

2-1-2 = Weighted percentage difference (3.85%) for catalog in Iteration 1 is too high. Expected: 22613 requests, Actual: 15187

2-1-3 = Weighted percentage difference (8.21%) for product in Iteration 1 is too high. Expected: 47847 requests, Actual: 32000

2-1-4 = Weighted percentage difference (7.36%) for fileCatalog in Iteration 1 is too high. Expected: 43500 requests, Actual: 29295

2-1-5 = Weighted percentage difference (4.33%) for file in Iteration 1 is too high. Expected: 26099 requests, Actual: 17739

2-1-6 = Weighted percentage difference (2.16%) for download in Iteration 1 is too high. Expected: 13055 requests, Actual: 8879

2-1-7 = Sum of weighted percentage difference (32.62%) exceeds 1.5% for Iteration 1
2-1-8 = Page home errors (10642) >= 0.01 * Requests ( 10642) = 106.42
2-1-9 = Page search errors (16389) >= 0.01 * Requests ( 16389) = 163.89000000000001
2-1-10 = Page catalog errors (15187) >= 0.01 * Requests ( 15187) = 151.87
2-1-11 = Page product errors (32000) >= 0.01 * Requests ( 32000) = 320.0
2-1-12 = Page fileCatalog errors (29295) >= 0.01 * Requests ( 29295) = 292.95
2-1-13 = Page file errors (17739) >= 0.01 * Requests ( 17739) = 177.39000000000001
2-1-14 = Page download errors (8879) >= 0.01 * Requests ( 8879) = 88.79
2-1-15 = Total validation errors (130131) >= 0.005 * TotalRequests ( 130131) =650.655
1-1-0 = Weighted percentage difference (2.59%) for home in Iteration 1 is too high. Expected: 15657 requests, Actual: 10647

1-1-1 = Weighted percentage difference (4.14%) for search in Iteration 1 is too high. Expected: 24358 requests, Actual: 16371

1-1-2 = Weighted percentage difference (3.84%) for catalog in Iteration 1 is too high. Expected: 22613 requests, Actual: 15201

1-1-3 = Weighted percentage difference (8.22%) for product in Iteration 1 is too high. Expected: 47847 requests, Actual: 31976

1-1-4 = Weighted percentage difference (7.39%) for fileCatalog in Iteration 1 is too high. Expected: 43500 requests, Actual: 29228

1-1-5 = Weighted percentage difference (4.35%) for file in Iteration 1 is too high. Expected: 26099 requests, Actual: 17699

1-1-6 = Weighted percentage difference (2.16%) for download in Iteration 1 is too high. Expected: 13055 requests, Actual: 8889

1-1-7 = Sum of weighted percentage difference (32.68%) exceeds 1.5% for Iteration 1
1-1-8 = Page home errors (10647) >= 0.01 * Requests ( 10647) = 106.47
1-1-9 = Page search errors (16371) >= 0.01 * Requests ( 16371) = 163.71
1-1-10 = Page catalog errors (15201) >= 0.01 * Requests ( 15201) = 152.01
1-1-11 = Page product errors (31976) >= 0.01 * Requests ( 31976) = 319.76
1-1-12 = Page fileCatalog errors (29228) >= 0.01 * Requests ( 29228) = 292.28000000000003
1-1-13 = Page file errors (17699) >= 0.01 * Requests ( 17699) = 176.99
1-1-14 = Page download errors (8889) >= 0.01 * Requests ( 8889) = 88.89
1-1-15 = Total validation errors (130011) >= 0.005 * TotalRequests ( 130011) =650.0550000000001
3-1-0 = Weighted percentage difference (2.60%) for home in Iteration 1 is too high. Expected: 15657 requests, Actual: 10641

3-1-1 = Weighted percentage difference (4.19%) for search in Iteration 1 is too high. Expected: 24358 requests, Actual: 16260

3-1-2 = Weighted percentage difference (3.86%) for catalog in Iteration 1 is too high. Expected: 22613 requests, Actual: 15166

3-1-3 = Weighted percentage difference (8.28%) for product in Iteration 1 is too high. Expected: 47847 requests, Actual: 31849

3-1-4 = Weighted percentage difference (7.43%) for fileCatalog in Iteration 1 is too high. Expected: 43500 requests, Actual: 29144

3-1-5 = Weighted percentage difference (4.38%) for file in Iteration 1 is too high. Expected: 26099 requests, Actual: 17649

3-1-6 = Weighted percentage difference (2.16%) for download in Iteration 1 is too high. Expected: 13055 requests, Actual: 8878

3-1-7 = Sum of weighted percentage difference (32.90%) exceeds 1.5% for Iteration 1
3-1-8 = Page home errors (10641) >= 0.01 * Requests ( 10641) = 106.41
3-1-9 = Page search errors (16260) >= 0.01 * Requests ( 16260) = 162.6
3-1-10 = Page catalog errors (15166) >= 0.01 * Requests ( 15166) = 151.66
3-1-11 = Page product errors (31849) >= 0.01 * Requests ( 31849) = 318.49
3-1-12 = Page fileCatalog errors (29144) >= 0.01 * Requests ( 29144) = 291.44
3-1-13 = Page file errors (17649) >= 0.01 * Requests ( 17649) = 176.49
3-1-14 = Page download errors (8878) >= 0.01 * Requests ( 8878) = 88.78
3-1-15 = Total validation errors (129587) >= 0.005 * TotalRequests ( 129587) =647.9350000000001
3-0-0 = Error reading file '/opt/SPECjAppServer2004/output/11/Atomicity.html'
3-0-1 = Error reading file '/opt/SPECjAppServer2004/output/11/ValidationErr.txt'
0-1-0 = Weighted percentage difference (2.60%) for home in Iteration 1 is too high. Expected: 15657 requests, Actual: 10633

0-1-1 = Weighted percentage difference (4.13%) for search in Iteration 1 is too high. Expected: 24358 requests, Actual: 16377

0-1-2 = Weighted percentage difference (3.83%) for catalog in Iteration 1 is too high. Expected: 22613 requests, Actual: 15211

0-1-3 = Weighted percentage difference (8.21%) for product in Iteration 1 is too high. Expected: 47847 requests, Actual: 31985

0-1-4 = Weighted percentage difference (7.38%) for fileCatalog in Iteration 1 is too high. Expected: 43500 requests, Actual: 29252

0-1-5 = Weighted percentage difference (4.34%) for file in Iteration 1 is too high. Expected: 26099 requests, Actual: 17711

0-1-6 = Weighted percentage difference (2.17%) for download in Iteration 1 is too high. Expected: 13055 requests, Actual: 8872

0-1-7 = Sum of weighted percentage difference (32.67%) exceeds 1.5% for Iteration 1
0-1-8 = Page home errors (10633) >= 0.01 * Requests ( 10633) = 106.33
0-1-9 = Page search errors (16377) >= 0.01 * Requests ( 16377) = 163.77
0-1-10 = Page catalog errors (15211) >= 0.01 * Requests ( 15211) = 152.11
0-1-11 = Page product errors (31985) >= 0.01 * Requests ( 31985) = 319.85
0-1-12 = Page fileCatalog errors (29252) >= 0.01 * Requests ( 29252) = 292.52
0-1-13 = Page file errors (17711) >= 0.01 * Requests ( 17711) = 177.11
0-1-14 = Page download errors (8872) >= 0.01 * Requests ( 8872) = 88.72
0-1-15 = Total validation errors (130041) >= 0.005 * TotalRequests ( 130041) =650.205
1-0-0 = Error reading file '/opt/SPECjAppServer2004/output/25/Atomicity.html'
1-0-1 = Error reading file '/opt/SPECjAppServer2004/output/25/ValidationErr.txt'
4-0-0 = Error reading file '/opt/SPECjAppServer2004/output/15/Atomicity.html'
4-0-1 = Dealer Purchase Transaction Mix: FAILED
4-0-2 = Dealer Manage Transaction Mix: FAILED
4-0-3 = Dealer Browse Transaction Mix: FAILED
4-0-4 = Dealer 90% Response Time FAILED
4-0-5 = Dealer Avg. Response Time FAILED
4-0-6 = Purchase Cycle Time Avg. FAILED
4-0-7 = Manage Cycle Time Avg. FAILED
4-0-8 = Browse Cycle Time Avg. FAILED
4-0-9 = Vehicle Purchasing Rate FAILED
4-0-10 = Largeorder Vehicle Purchase Rate FAILED
4-0-11 = Regular Vehicle Purchase Rate FAILED
4-0-12 = LargeOrderLine Vehicle Rate FAILED
4-0-13 = PlannedLines Vehicle Rate FAILED
4-0-14 = Manufacturing 90% Response Time FAILED
2-0-0 = Error reading file '/opt/SPECjAppServer2004/output/18/Atomicity.html'
2-0-1 = Error reading file '/opt/SPECjAppServer2004/output/18/ValidationErr.txt'
4-2-0 = UID_STORE_NUM_UNSET_FLAGS_SEEN Mix Pct Failed. Expected: 30.000, Achieved: 31.288
0-0-0 = Dealer Purchase Transaction Mix: FAILED
0-0-1 = Dealer Manage Transaction Mix: FAILED
0-0-2 = Dealer Browse Transaction Mix: FAILED
0-0-3 = Dealer 90% Response Time FAILED
0-0-4 = Dealer Avg. Response Time FAILED
0-0-5 = Purchase Cycle Time Avg. FAILED
0-0-6 = Manage Cycle Time Avg. FAILED
0-0-7 = Average vehicles per order FAILED
0-0-8 = Vehicle Purchasing Rate FAILED
0-0-9 = Percent Purchases that are Large Orders FAILED
0-0-10 = Average # of vehicles per regular order FAILED
0-0-11 = Regular Vehicle Purchase Rate FAILED
0-0-12 = LargeOrderLine Vehicle Rate FAILED
0-0-13 = Manufacturing 90% Response Time FAILED
2017-09-28 02:55:04:647 PrimeControl: aggregate audit...
2017-09-28 02:55:04:648 PrimeControl: aggregate audit...
2017-09-28 02:55:04:648 PrimeControl: aggregate audit...
2017-09-28 02:55:04:649 PrimeControl: aggregate audit...
2017-09-28 02:55:04:649 PrimeControl: aggregate audit...
2017-09-28 02:55:04:650 PrimeControl: aggregate audit...
2017-09-28 02:55:04:651 PrimeControl: aggregate audit...
2017-09-28 02:55:04:651 PrimeControl: aggregate audit...
2017-09-28 02:55:04:652 PrimeControl: aggregate audit...
2017-09-28 02:55:04:655 PrimeControl: aggregate audit...
2017-09-28 02:55:04:655 PrimeControl: aggregate audit...
2017-09-28 02:55:04:656 PrimeControl: aggregate audit...
2017-09-28 02:55:04:656 PrimeControl: aggregate audit...
2017-09-28 02:55:04:657 PrimeControl: aggregate audit...
2017-09-28 02:55:04:657 PrimeControl: aggregate audit...
2017-09-28 02:55:04:664 PrimeControl: aggregate audit...
2017-09-28 02:55:04:670 PrimeControl: aggregate audit...
2017-09-28 02:55:04:672 PrimeControl: aggregate audit...
2017-09-28 02:55:04:675 PrimeControl: aggregate audit...
2017-09-28 02:55:04:675 PrimeControl: aggregate audit...
2017-09-28 02:55:04:675 PrimeControl: validating aggregate audit...
Exception in thread "Thread-18" java.lang.NullPointerException
   at java.util.Hashtable.put(Hashtable.java:514)
   at org.spec.virt.Configuration.setValue(Configuration.java:201)
   at org.spec.virt.Configuration.setValue(Configuration.java:192)
   at org.spec.virt.PrimeControl.printPrimeMetrics(PrimeControl.java:1154)
   at org.spec.virt.PrimeControl.access$2200(PrimeControl.java:32)
   at org.spec.virt.PrimeControl$PrimeClientThread.run(PrimeControl.java:1904)
Exception in thread "Thread-26" java.lang.NullPointerException
   at java.util.Hashtable.put(Hashtable.java:514)
   at org.spec.virt.Configuration.setValue(Configuration.java:201)
   at org.spec.virt.Configuration.setValue(Configuration.java:192)
   at org.spec.virt.PrimeControl.printPrimeMetrics(PrimeControl.java:1154)
   at org.spec.virt.PrimeControl.access$2200(PrimeControl.java:32)
   at org.spec.virt.PrimeControl$PrimeClientThread.run(PrimeControl.java:1904)
Exception in thread "Thread-22" java.lang.NullPointerException
   at java.util.Hashtable.put(Hashtable.java:514)
   at org.spec.virt.Configuration.setValue(Configuration.java:201)
   at org.spec.virt.Configuration.setValue(Configuration.java:192)
   at org.spec.virt.PrimeControl.printPrimeMetrics(PrimeControl.java:1154)
   at org.spec.virt.PrimeControl.access$2200(PrimeControl.java:32)
   at org.spec.virt.PrimeControl$PrimeClientThread.run(PrimeControl.java:1904)
        ....

This symptom did not occur in tile1 and tile2, but existed in tile3~tile5.
(I found the disk usage of both tile1 and tile2 didn't decrease after a run.)
The usage of storage in tile3 tile4 and tile5 is as follows:
before executing runspecvirt.sh
[root@appserver Desktop]# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/vda3        33G  7.6G   24G  25% /
tmpfs           4.0G  224K  4.0G   1% /dev/shm
/dev/vda1      1008M   62M  896M   7% /boot

after executing runspecvirt.sh
[root@appserver Desktop]# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/vda3        33G   33G    0 100% /
tmpfs           4.0G  224K  4.0G   1% /dev/shm
/dev/vda1      1008M   62M  896M   7% /boot

Should I re-install appservers with larger volume?
How do I determine how much it needs to run 5 or more tiles?

Thanks.

[lroderic]

Hi. One of the subcommittee members uses the following to clean up appserver between test runs:

Code: [Select]

$sjasprimedir = /opt/SPECjAppServer2004/
echo "0" >~/specjappserver.seq
rm -rf $sjasprimedir/classes/*.txt
rm -rf $sjasprimedir/output/*
echo -n "0" >$sjasprimedir/output/specjappserver.seq
mkdir -p $sjasprimedir/output/0
touch $sjasprimedir/output/0/Atomicity.html

That you're running out of disk space means you're filling log files with errors.

Lisa

[Miles]

Hi
I have completed a 3T4W run but validation errors in Application Server and Web Server are as follows:

Code: [Select]

Application Server Errors:
◾Dealer Purchase Transaction Mix: FAILED
◾Dealer Manage Transaction Mix: FAILED
◾Dealer Browse Transaction Mix: FAILED
◾Dealer 90% Response Time FAILED
◾Dealer Avg. Response Time FAILED
◾Purchase Cycle Time Avg. FAILED
◾Manage Cycle Time Avg. FAILED
◾Average vehicles per order FAILED
◾Vehicle Purchasing Rate FAILED
◾Percent Purchases that are Large Orders FAILED
◾Average # of vehicles per regular order FAILED
◾Regular Vehicle Purchase Rate FAILED
◾LargeOrderLine Vehicle Rate FAILED
◾PlannedLines Vehicle Rate FAILED
◾Manufacturing 90% Response Time FAILED

Web Server Errors:
◾Page file errors (171421) >= 0.01 * Requests ( 175025) = 1750.25
◾Total validation errors (171421) >= 0.005 * TotalRequests ( 1290937) =6454.685

◦ Aggregate Audit for Shared Database
◾Database 1 Errors: ◾Work Order Transaction validation FAILED
◾PO Transaction validation FAILED
◾POLine Transaction validation: WARNING: New POLine DB Count ~ Delivery Servlet Tx Count > 10%
◾Manufacturing Delivery Statistics: WARNING: Number of depleted components higher than expected!

Code: [Select]

[1] The following working means the Glassfish server is running:
http://specdelivery:8000/"Your server is now running' was returned.

Code: [Select]

[2] The following returning 200 OK means the SPECjAppServer.ear deployed on the GlassFish:
curl http://specdelivery:8000/Supplier/DeliveryServlet?cmd=switchlog"200 OK" was returned.

Code: [Select]

[3] Once deployment works, then verify DB connectivity:
curl http://specdelivery:8000/SPECjAppServer/app?action=atomicityTests"PASSED" was returned.

I followed ExampleVM script to setup the VMs and executed jAppInit.sh/jAppInitRstr.sh before a new run.

Which steps did I miss or correct?

Thanks.

[DavidSchmidt]

Hi Miles. Would you please attach the primectrl.out file and the results/[run-dir]/1-1.0/*_Audit.report files for this run? These will help to determine how the runs are failing QoS. Thanks,

[Miles]

Hi
The logs are attached.

I found "Conflict invalid XML format" error appeared in the server.log on appservers as ollows:

[#|2017-10-24T16:02:26.703+0800|SEVERE|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=319;_ThreadName=Thread-2;|org.spec.jappserver.common.SPECjAppServerException: Remote side error: 409 Conflict invalid XML format

0-0_Dealer.summary

Code: [Select]

Dealer Summary Report
Version : SPECjAppServer2004 v1.08


Dealer Transaction Rate : 0.00 Transactions/sec

TRANSACTION MIX

Total number of transactions = 5
TYPE TX. COUNT MIX REQD. MIX.(5% Deviation Allowed)
---- --------- --- ----------
Purchase: 00001 20.00% 25% FAILED
Manage     : 00004 80.00% 25% FAILED
Browse Autos: 00000 0.00% 50% FAILED

RESPONSE TIMES AVG. MAX. 90TH% REQD. 90TH%

Purchase 246.146 246.146 0.100 2
Manage        551.489 732.166 10.000 2
Browse    0.000 0.000 0.000

Requirement for 90% Response Time FAILED
Requirement for Avg. Response Time FAILED


CYCLE TIMES TARGETED AVG. ACTUAL AVG. MIN. MAX.

Purchase 23.753 552.320 0.000 552.320 FAILED
Manage    7.165 1190.950 0.000 1525.712 FAILED
Browse    0.000 0.000

MISC. STATISTICS

Average vehicles per order 17.000 FAILED
Vehicle Purchasing Rate 0.002/sec FAILED
Percent Purchases that are Large Orders 0.00 FAILED
Average # of vehicles per Large Order 0.000 PASSED
Largeorder Vehicle Purchase Rate 0.000/sec PASSED
Average # of vehicles per regular order 17.000 FAILED
Regular Vehicle Purchase Rate 0.002/sec FAILED


 -- SUNDRY COUNTS (no pass/fail) --

Purchase: denied due to bad credit 00000
Purchase: vehicles immediate txns 00000
Purchase: vehicles deferred txns 00001
Purchase: cart clears 00000
Purchase: vehicles removed from cart 00000
Manage: open orders cancelled 00000
Manage: vehicles sold from lot 00041
Manage: average vehicles sold per txn 00010
Manage: application level errors 00000
Browse: forwards 00000
Browse: backwards 00000
Logins:                1
Trans/sec(txPerSec): 0.001
purcPer:        20.000
percentLrgDealer: 0.000
sumPurcOlCnt:       17
sumPurcLrgOlCnt:     0
sumPurcCount:        1
sumPurcLrgCnt:        0


LITTLE'S LAW VERIFICATION


Number of users = 2250
Sum of Avg. RT * TPS for all Tx. Types = 0.738350



Thanks for your help.

[Miles]

Hi
Should I provide other log or messages to debug?

Thanks.

[DavidSchmidt]

Hi Miles.

It looks like you are not really getting any appserver workload traffic. For a 2-hour run, your TX counts should be closer to 180K for purchase and Manage and 360K for Browse Autos. The error you see regarding and invalid XML format is probably the issue. Can you post your server.xml file from the appserver?

Thanks,

[Miles]

Hi
I download Apache Tomcat 7.0.54 from the URL describled in "SPECvirt_sc2013 Example VM Setup Guide".

I am not sure which one is so I attach 3 files as follows:
"server-1.xml" is copied from /etc/tomcat6/
"server-2.xml" is copied from /opt/apache-tomcat_7.0.54/conf/
"server-3.xml" is copied for /opt/tomcat/conf

Thanks.

[DavidSchmidt]

Hi Miles. The errors you are seeing were seen during our development when the appserver workload (SPECjAppServer.ear) and emulator (emulator.ear/war) are not in sync on the SUT VMs. Please check your appserver (Glassfish) server.log file and emulator (Tomcat) log for conflict errors on all of your tiles.

Also, please verify that the SPECjAppserver.ear file and emulator.war file on your SUT VMs in your Glassfish environment match the original versions provided in the SPECvirt_sc2013 kit in the /opt/SPECjAppServer2004/jars directory. There should be no need to rebuild either file for your environment.

[Miles]

Hi
I added IP of appserver VMs to pg_hba.conf then used command
 "service postgresql-9.4 restart" ,but the symptom still exist.

I have checked the appserver (Glassfish) server.log file and emulator (Tomcat) log and found the following message:

Code: [Select]

[#|2017-11-06T18:50:47.381+0800|INFO|glassfish3.1.2|javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions|_ThreadID=86;_ThreadName=Thread-2;|JTS5078: Table for transaction logging was not added.|#]
Then I copied SPECvirt_sc2013 kit to overwrite my SPECjApp folder on dbserver and re-run, but got the same validation errors.

I think I didn't realize what you mean.

Thanks.