Poor Performance When Requesting JSON Data

[zorlack]

Hello,

I’m seeing a performance issue which I can’t figure out.

I have an API endpoint which returns data from a OrmLite query.

When I request the page without any “Accept” header the page performs extremely well.

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -H "Cookie: ss-id=PZgbO14exQKkQF72Fs3l; ss-pid=HAyYGBgA1pK6E7eMMGSH; ss-opt=temp; X-UAId=1" -o NUL
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  288k    0  288k    0     0  4659k      0 --:--:-- --:--:-- --:--:-- 4659k
    time_namelookup:  0.000000
       time_connect:  0.000000
    time_appconnect:  0.000000
   time_pretransfer:  0.015000
      time_redirect:  0.000000
 time_starttransfer:  0.062000
                    ----------
         time_total:  0.062000

Here you can see that we downloaded 288KB from localhost in 62ms. There are no razor templates at play here, so the resulting HTML is the default ServiceStack data renderer which appears itself to be based on the JSON data.

When I go to test the performance of endpoint using Accept: application/json performance is significantly degraded:

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -H "Cookie: ss-id=PZgbO14exQKkQF72Fs3l; ss-pid=HAyYGBgA1pK6E7eMMGSH; ss-opt=temp; X-UAId=1" -H "Accept: application/json" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  279k    0  279k    0     0   119k      0 --:--:--  0:00:02 --:--:--  119k
    time_namelookup:  0.000000
       time_connect:  0.000000
    time_appconnect:  0.000000
   time_pretransfer:  0.000000
      time_redirect:  0.000000
 time_starttransfer:  0.047000
                    ----------
         time_total:  2.344000

Here you can see that despite returning slightly less data (because no HTML is included) the query took more than 2000ms.

I don’t think this is related to any kind of caching because the discrepancy is consistent even right after startup.

This feels to me like it may be a routing problem or something, but I’m not at all sure where to look.

The Service Model looks like this:

namespace ServiceStackWithFrontend.ServiceModel
{
    [Route("/api/broadcast/stations")]
    public class GetStations : IReturn<StationListResponse>
    {
    }
    public class StationListResponse
    {
        public List<Station> Stations { get; set; }
    }
}

And the service itself looks like this:

public class BroadcastService : Service
{
    private readonly IDbConnectionFactory dbFactory;
  
    public  BroadcastService(IDbConnectionFactory factory)
    {
        this.dbFactory = factory;
    }
    [Authenticate]
    public Object Get(GetStations request)
    {
        StationListResponse response = new StationListResponse();           
        using (var db = dbFactory.OpenDbConnection())
        {
            response.Stations = db.Select<Station>(s => s.Active == 1);
        }
        return response;
    }
}

It’s being manually registered in the App using this:

container.Register(new BroadcastService(new OrmLiteConnectionFactory(container.Resolve<IAppSettings>().GetString("OrmLiteMMSConnectionString"), SqlServerDialect.Provider)));

Any idea why there would be such a significant performance discrepancy?

[zorlack]

In diving in a bit deeper here, I’m starting to think this may be cache related.

When I change the service to include a CacheResponse attribute like this:

[CacheResponse(CacheControl=CacheControl.NoCache)]
public class BroadcastService : Service
{
    private readonly IDbConnectionFactory dbFactory;
  
    public  BroadcastService(IDbConnectionFactory factory)
    {
        this.dbFactory = factory;
    }
    [Authenticate]
    public Object Get(GetStations request)
    {
        StationListResponse response = new StationListResponse();           
        using (var db = dbFactory.OpenDbConnection())
        {
            response.Stations = db.Select<Station>(s => s.Active == 1);
        }
        return response;
    }
}

The performance discrepancy goes away.

EDIT: This might be irrelevant. Since I think all I’ve accomplished here is to turn on caching and send a no-cache header.

[mythz]

No idea why you’d see a penalty with an application/json response, does the penalty still exist when you request a JSON response without using the Accept header, i.e:

/api/broadcast/stations.json
/api/broadcast/stations?format=json

[mythz]

BTW is there any reason you’re not using the built in base.Db property? i.e:

public object Get(GetStations request) =>
    new StationListResponse {
        Stations = Db.Select<Station>(s => s.Active == 1)
    };

[zorlack]

Yes, the discrepancy is still there.

To simplify the test I’ve removed the Authenticate requirement and performed each CURL test after a fresh restart of the application.

The results similar.

Here’s the request for the HTML version

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  288k    0  288k    0     0   410k      0 --:--:-- --:--:-- --:--:--  410k
    time_namelookup:  0.000000
       time_connect:  0.000000
    time_appconnect:  0.000000
   time_pretransfer:  0.000000
      time_redirect:  0.000000
 time_starttransfer:  0.688000
                    ----------
         time_total:  0.703000

Here’s the request with the JSON version.

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?format=json" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  279k    0  279k    0     0  80396      0 --:--:--  0:00:03 --:--:-- 80396
    time_namelookup:  0.000000
       time_connect:  0.000000
    time_appconnect:  0.000000
   time_pretransfer:  0.000000
      time_redirect:  0.000000
 time_starttransfer:  0.375000
                    ----------
         time_total:  3.562000

Another factor could be that I’m running this as a Stand-Alone application.

Here’s our AppHost.Configure:

public override void Configure(Container container)
    {
        SetConfig(new HostConfig
        {
            WebHostPhysicalPath = "client-side"
        });


        container.Register<IAppSettings>(new AppSettings());
        container.Register<IDbConnectionFactory>(c => new OrmLiteConnectionFactory(container.Resolve<IAppSettings>().GetString("OrmLiteConnectionString"), SqliteDialect.Provider)); //InMemory Sqlite DB
        container.Register<ICacheClient>(new MemoryCacheClient());
        container.Register<IUserAuthRepository>(new OrmLiteAuthRepository(container.Resolve<IDbConnectionFactory>()));
        container.Register(new BroadcastService(new OrmLiteConnectionFactory(container.Resolve<IAppSettings>().GetString("OrmLiteMMSConnectionString"), SqlServerDialect.Provider)));
        ValidateAuthenticationScheme(container);


        this.Plugins.Add(new AuthFeature(() => new AuthUserSession(), 
          new IAuthProvider[] {
                new CredentialsAuthProvider(),
          }, 
          "/#login")
        );

        this.Plugins.Add(new AdminFeature());
        this.Plugins.Add(new AutoQueryFeature { MaxLimit = 100 });
        this.Plugins.Add(new RegistrationFeature());
        this.Plugins.Add(new PostmanFeature());
        this.Plugins.Add(new CorsFeature());

        this.GlobalResponseFilters.Add((request, response, responseDto) =>
        {
            if (response.Dto != null && response.Dto.GetType() == typeof(AuthenticateResponse))
            {
                ((AuthenticateResponse)response.Dto).Meta = new Dictionary<string, string>();
                ((AuthenticateResponse)response.Dto).Meta["Roles"] = request.GetSession().Roles.ToJson();
            }
        });
    }

The reason for the Database connection weirdness is that I’m using OrmLite to connect to two distinct database services. One specifically for this service.

[mythz]

that’s really strange, the html should be using the same JSON serialization but embedded in a HTML page.

Can you confirm that the html version that’s returned also includes the same json in:

var model = {JSON},

[zorlack]

Yes, the HTML version uses the exact same JSON blob as is produced by format=json. (Same exact byte count)

I added a little bit of debug logging and have confirmed that the query portion of the code is consistently fast. The delay seems to occur after I return the response from the Get function.

[mythz]

Could you do some profiling (e.g dotTrace has a free demo period) so we can workout where the time is being spent? Otherwise we’d need a stand-alone repro we could investigate ourselves.

[zorlack]

I’m not very familiar with dotTrace, but here’s what I see.

First: The Request.

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?format=json" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  279k    0  279k    0     0  56573      0 --:--:--  0:00:05 --:--:-- 62134
    time_namelookup:  0.015000
       time_connect:  0.015000
    time_appconnect:  0.000000
   time_pretransfer:  0.015000
      time_redirect:  0.000000
 time_starttransfer:  0.296000
                    ----------
         time_total:  5.062000

The HTTP request portion of the call seems to perform relatively quickly (280ms):

When I back up and look at a broader context I see that most of the time is being spent in ServiceStack.Text.Common.WriteListsOfElements:

Could this be something to do with my Station POCO? It looks like this:

[Alias("Stations")]
public class Station
{
    public int StationID { get; set; }
    [Alias("UniqueIdentifier")]
    public string StationGUID { get;set;}
    public string StationName { get; set; }
    [Alias("MarketID")]
    public int MarketId { get; set; }
    public short MediaType { get; set; }
    public short Active { get; set; }
    public string NationalNetwork { get; set; }
}

Many thanks!

-Z

[mythz]

Doesn’t look like it should, but I’ll check. Can you confirm these are all the DTO classes used in that service?

[Route("/api/broadcast/stations")]
public class GetStations : IReturn<StationListResponse>
{
}
public class StationListResponse
{
    public List<Station> Stations { get; set; }
}
[Alias("Stations")]
public class Station
{
    public int StationID { get; set; }
    [Alias("UniqueIdentifier")]
    public string StationGUID { get;set;}
    public string StationName { get; set; }
    [Alias("MarketID")]
    public int MarketId { get; set; }
    public short MediaType { get; set; }
    public short Active { get; set; }
    public string NationalNetwork { get; set; }
}

[zorlack]

Here’s what the HTML request looks like.

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  288k    0  288k    0     0   802k      0 --:--:-- --:--:-- --:--:--  802k
    time_namelookup:  0.016000
       time_connect:  0.016000
    time_appconnect:  0.000000
   time_pretransfer:  0.016000
      time_redirect:  0.000000
 time_starttransfer:  0.329000
                    ----------
         time_total:  0.360000

Note that HandleResponse looks very different in this call:

[zorlack]

Here’s the complete service:

public class BroadcastService : Service
{
    private readonly IDbConnectionFactory dbFactory;
    public static ILog Log = LogManager.GetLogger(typeof(BroadcastService));

    public  BroadcastService(IDbConnectionFactory factory)
    {
        this.dbFactory = factory;
    }
    
    public Object Get(GetStations request)
    {
        StationListResponse response = new StationListResponse();           
        using (var db = dbFactory.OpenDbConnection())
        {
            response.Stations = db.Select<Station>(s => s.Active == 1);
        }
        Log.Debug("Query Complete.");
        return response;
    }

    public Object Get(GetMarkets request)
    {
        MarketListResponse response = new MarketListResponse();
        using (var db = dbFactory.OpenDbConnection())
        {
            response.Markets = db.LoadSelect<Market>(m => m.Active == true);
        }
        return response;
    }

    public Object Get(GetCountries request)
    {
        CountryListResponse response = new CountryListResponse();
        response.Countries = new List<Country>();

        List<Market> marketList = new List<Market>();
        using (var db = dbFactory.OpenDbConnection())
        {
            marketList = db.LoadSelect<Market>(m => m.Active == true);
        }

        foreach(String countryCode in marketList.Select(m => m.Country).Distinct().ToList())
        {
            List<State> countryStates = new List<State>();
            foreach(String state in marketList.Where(m => m.Country == countryCode && m.State != null && m.State.Length > 0).Select(m => m.State).Distinct().ToList())
            {
                countryStates.Add(new State { StateCode = state, Markets = marketList.Where(m => m.Country == countryCode && m.State == state).ToList() });
            }
            var country = new Country
            {
                CountryCode = countryCode,
                Markets = marketList.Where(m => m.Country == countryCode && (m.State == null || m.State.Trim().Length == 0)).ToList(),
                States = countryStates
            };
            response.Countries.Add(country);
        }
        return response;
    }
}

Here are the Underlying classes:

[Alias("Stations")]
public class Station
{
    public int StationID { get; set; }
    [Alias("UniqueIdentifier")]
    public string StationGUID { get;set;}
    public string StationName { get; set; }
    [Alias("MarketID")]
    public int MarketId { get; set; }
    public short MediaType { get; set; }
    public short Active { get; set; }
    public string NationalNetwork { get; set; }
}
public class Market
{
    public int MarketID { get; set; }
    public string MarketName { get; set; }
    public string Country { get; set; }
    public bool Active { get; set; }
    //public int? FilterOrder { get; set; }
    //public string DefaultAccess { get; set; }
    public string State { get; set; }
    public string Latitude { get; set; }
    public string Longitude { get; set; }
    public int? DMARank { get; set; }
    [Reference]
    public List<Station> Stations { get; set; }
}
public class Country
{
    public String CountryCode { get; set; }
    public List<State> States { get; set; }
    public List<Market> Markets { get; set; }
}
public class State
{
    public String StateCode { get; set; }
    public List<Market> Markets { get; set; }
}

Here is the Service Model:

    [Route("/api/broadcast/stations")]
    public class GetStations : IReturn<StationListResponse>
    {
    }
    public class StationListResponse
    {
        public List<Station> Stations { get; set; }
    }

    [Route("/api/broadcast/markets")]
    public class GetMarkets : IReturn<MarketListResponse>
    {
    }
    public class MarketListResponse
    {
        public List<Market> Markets { get; set; }
    }

    [Route("/api/broadcast/countries")]
    public class GetCountries : IReturn<CountryListResponse>
    {
    }
    public class CountryListResponse
    {
        public List<Country> Countries { get; set; }
    }

[xplicit]

@zorlack How many elements of Station are returned by your service? If the record is small in length and number of records is large then performance degradation could be caused by auto-flushing when response uses chunked encoding. Need to confirm that this is your case to make a fix for it.

[zorlack]

The query should be returning about 3,000 results - so quite a large dataset. However, the same sized data set is being returned via the Default HTML handler. (Not sure if that’s relevant or not)

One other thing to note, I’ve now added a search parameter to my service which lets me restrict the list of content being returned. Here’s a a test which only returns 3 results:

Default HTML Handler (After a fresh start):

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?search=CSPAN" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  9924    0  9924    0     0  57697      0 --:--:-- --:--:-- --:--:-- 57697
    time_namelookup:  0.016000
       time_connect:  0.016000
    time_appconnect:  0.000000
   time_pretransfer:  0.016000
      time_redirect:  0.000000
 time_starttransfer:  0.172000
                    ----------
         time_total:  0.172000

Format=JSON request for the same content (After a fresh start):

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?search=CSPAN&format=json" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   382    0   382    0     0   1632      0 --:--:-- --:--:-- --:--:--  1632
    time_namelookup:  0.000000
       time_connect:  0.000000
    time_appconnect:  0.000000
   time_pretransfer:  0.000000
      time_redirect:  0.000000
 time_starttransfer:  0.219000
                    ----------
         time_total:  0.234000

After repeatedly hammering this interface, it seems that small results sets return in roughly the same amount of time regardless of whether the content comes from the HTML handler or the JSON handler.

I suspect you may be right that this is related to chunking or some other transmission-related function.

[zorlack]

We’ve been doing a bit of Wireshark testing and I do think that this is due to Chunked-Encoding.

When requesting the HTML version of the page we see that data is sent in 2 chunks

However, when requesting the raw JSON for the same content I see the data sent in over 6,000 tiny chunks:

I think this confirms your suspicions.

[xplicit]

@zorlack I just pushed the change to MyGet which should resolve the issue with chunked encoding. Can you check the latest v4.5.9 from MyGet and tell does it help in your case?

[zorlack]

@xplicit That seems to have done it. I now see we’re creating far-fewer TCP segments when requesting JSON content.

For reference, our latest HTML test returned 27,128KB over 4 packets.

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/markets?search=new" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 26763    0 26763    0     0   104k      0 --:--:-- --:--:-- --:--:--  104k
    time_namelookup:  0.000000
       time_connect:  0.000000
    time_appconnect:  0.000000
   time_pretransfer:  0.000000
      time_redirect:  0.000000
 time_starttransfer:  0.250000
                    ----------
         time_total:  0.250000

The JSON test returned 17,739KB over 18 packets. The new packets are larger than 1000B (instead of being around 60B).

M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/markets?search=new&format=json" -o out.txt
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 17241    0 17241    0     0  27585      0 --:--:-- --:--:-- --:--:-- 27585
    time_namelookup:  0.000000
       time_connect:  0.000000
    time_appconnect:  0.000000
   time_pretransfer:  0.000000
      time_redirect:  0.000000
 time_starttransfer:  0.609000
                    ----------
         time_total:  0.625000

These examples are first-requests. Subsequent requests are significantly faster and HTML/JSON now compare favorably.

Many thanks for looking into this!

-Z

[xplicit]

It’s interesting that returning data in 4 big packets gets significant less time than returning data in 18 * 1K blocks. If this is not measurement fluctuation that means the buffer for chunked encoding should be larger than default buffer of 1024 bytes.

[zorlack]

Is that buffer size user-configurable or is that a hard-coded thing?

[xplicit]

This size of buffer is used in .NET StreamWriter implementation. It cannot be changed directly in user code.